Apr 3, 2010

Pre-python gdb scripting: recursive data structures (part 2/2)

1. Introduction

In this post, I'll continue describing usage of the gdb applied to analysis of recursive data structures, started in part 1.

In the course of this installment, we will gradually improve a set of custom gdb script functions to achieve automated printing of InlineTree class from Sun's hotspot JVM's core dumps. We will start by picking up a test which crashes JVM with a segfault. Then, we will slightly improve the dump_symbol gdb function created in the previous part by using gdb logging trick. Finally, we will implement stack for gdb script functions, and create the function for printing contents of any InlineTree instance, given a pointer.

As I will refer to things introduced in the previous part, it might be a good idea to start reading from there.

2. Getting started

InlineTree structure holds information about which methods were inlined in the process of compilation. It has a recursive structure, i.e. every object of InlineTree class has a list of pointers to children InlineTree objects. Naturally, we would like to have such core dump generated during compilation, that InlineTree object would be non-trivial. There are means to artificially increase InlineTree depth for the illustrative purposes, which we will employ.

One good place to search for Java programs able to segfault the JVM in the process of Java method compilation, is OpenJDK's regression tests against compiler. I already have them as they were cloned from mercurial together with hotspot's sources:

$hg clone http://hg.openjdk.java.net/jdk6/jdk6/hotspot hotspot

The compiler tests are in hotspot/test/compiler.

2.1. Obtaining a core

After some digging through these tests, I selected the test 6855164, as it segfaults on JVM 1.6.0_16, when executed with '-server' command-line switch:

Example 1. Generating a core dump

6855164$ ulimit -c unlimited
6855164$ javac Test.java
6855164$ java -server Test
#
# A fatal error has been detected by the Java Runtime Environment:
#
#  SIGSEGV (0xb) at pc=0xb71ae55f, pid=31620, tid=2874338160
#
# JRE version: 6.0_16-b01
# Java VM: Java HotSpot(TM) Server VM (14.2-b01 mixed mode linux-x86 )
# Problematic frame:
# V  [libjvm.so+0x5b555f]
#
# An error report file with more information is saved as:
# .../6855164/hs_err_pid31620.log
#
# If you would like to submit a bug report, please visit:
#   http://java.sun.com/webapps/bugreport/crash.jsp
#
Aborted (core dumped)
6855164$


Now, since original test has too simple (in inlining sense) failing method, I've added a call to System.out.println(), and forced some inlining to happen by using command-line switch:

6855164$ java -server -XX:CompileCommand=inline,java*::* Test

Example 2. 6855164 test source, freely available via OpenJDK

/*
 * Copyright 2009 Sun Microsystems, Inc.  All Rights Reserved.
 * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
 *
 * This code is free software; you can redistribute it and/or modify it
 * under the terms of the GNU General Public License version 2 only, as
 * published by the Free Software Foundation.
 *
 * This code is distributed in the hope that it will be useful, but WITHOUT
 * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
 * FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License
 * version 2 for more details (a copy is included in the LICENSE file that
 * accompanied this code).
 *
 * You should have received a copy of the GNU General Public License version
 * 2 along with this work; if not, write to the Free Software Foundation,
 * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
 *
 * Please contact Sun Microsystems, Inc., 4150 Network Circle, Santa Clara,
 * CA 95054 USA or visit www.sun.com if you need additional information or
 * have any questions.
 */

/*
 * @test
 * @bug 6855164
 * @summary SIGSEGV during compilation of method involving loop over CharSequence
 * @run main/othervm -Xbatch Test
 */
public class Test{
    public static void main(String[] args) throws Exception {
        StringBuffer builder = new StringBuffer();

        for(int i = 0; i < 100; i++)
            builder.append("I am the very model of a modern major general\n");

        for(int j = 0; j < builder.length(); j++){
            previousSpaceIndex(builder, j);
        }
    }

    private static final int previousSpaceIndex(CharSequence sb, int seek) {
        System.out.print(".");    // this line was added
        seek--;
        while (seek > 0) {
            if (sb.charAt(seek) == ' ') {
                while (seek > 0 && sb.charAt(seek - 1) == ' ')
                    seek--;
                return seek;
            }
            seek--;
        }
        return 0;
    }
}


2.2. Improving dump_symbol

First, let's see how we can improve the dump_symbol function, created earlier:

Example 3. Gdb script function for printing symbolOop*

define dump_symbol
  set $symboloop_length_offset = 8
  printf "%s", ($arg0)+$symboloop_length_offset+2
end
document dump_symbol
  Prints symbolOop at address arg0
end


This function has a flaw, since "%s" format relies on the char sequence ending with '\0' and SymbolOopDesc's _body doesn't guarantee that. This can lead to printing of some garbage (though it's not too bad usually, for gdb).

Anyway, as long as we know exact length of the string, we could use precision specifier "%.Ns" and print only the requested number of characters:

Example 4. First attempt to print limited number of characters

define read_2
  set $$arg0 = *(short*)($arg1)
end
document read_2
  Reads 2 bytes from address $arg1 to a variable named by $arg0
end

define dump_symbol
  set $symboloop_length_offset = 8
  read_2 sym_len ($arg0)+$symboloop_length_offset
  printf "%.$sym_lens" ($arg0)+$symboloop_length_offset+2
end
document dump_symbol
  Prints symbolOop at address arg0
end

This code tries to first read the length field to the variable named sym_len, and then use is as a format precision specifier. Unfortunately, this doesn't work, as gdb scripting language doesn't evaluate $sym_len and lefts it as is.


OK, so the naive attempt failed. What if we define custom gdb function 'nprintf', to which we would pass two arguments, number of characters to print, and address of a string (in hope gdb script will evaluate arg0 and arg1 inside format string):

Example 5. Second attempt, custom nprintf gdb function

define nprintf
  printf "%.$arg0s\n", $arg1
end

Let's see if it works for some valid string address:

(gdb) nprintf 4 0xaf9bf14a
java
(gdb) nprintf 10 0xaf9bf14a
java/io/Pr
(gdb)

Looks good! Unfortunately, this doesn't work either:

define dump_symbol
  set $symboloop_length_offset = 8
  read_2 sym_len ($arg0)+$symboloop_length_offset
  nprintf $sym_len ($arg0)+$symboloop_length_offset+2
end

(gdb) dump_symbol 0xaf9bf140
Unrecognized format specifier '$' in printf
(gdb)

Again, $sym_len goes unevaluated into format specifier.


We need some way to force the evaluation of a gdb variable. This is where the "gdb logging trick" comes into play. Consider this:

Example 6. Generating nprintf function dynamically

define generate_nprintf
  printf "define printf_n\n  printf \"%%.%ds\", ($arg%d)\nend\n", ($arg0), 0
end

(gdb) generate_nprintf 42
define printf_n
  printf "%.42s", ($arg0)
end
(gdb)

So, generate_nprintf generates the code of a printf_n function (a closure, if you wish), which prints exactly the specified number of string characters. If only we had a way of loading this generated code into gdb and use it. And such a way exists.


Since gdb scripts are loaded with 'source' command from the file, all we need is to print the code of a generated function to some external file and load it. Luckily for us, this functionality is already present in the gdb:

set logging file -- Set the current logfile
set logging off -- Disable logging
set logging on -- Enable logging
set logging overwrite -- Set whether logging overwrites or appends to the log file
set logging redirect -- Set the logging output mode

(gdb) help set logging redirect
Set the logging output mode.
If redirect is off, output will go to both the screen and the log file.
If redirect is on, output will go only to the log file.
(gdb)

Thus, the general plan would be:

  • Use some file, say, 'gdb.txt' as a logging file (initialize it in the beginning and enable logging)

  • When we need to generate custom printf_n function:

    • turn on logging redirect, so normal output is not messed up

    • call generate_nprintf (the code is appended to gdb.txt)

    • turn off redirection

    • get several last lines of gdb.txt and use them as input to 'source' command

  • Proceed with printf_n usage

After some tweaking, code for printf_n generation and usage looks like this:

Example 7. Improved dump_symbol code

# simple 'set logging redirect on/off' doesn't seem to be enough, thus this trick
define log_redirect_on
    set logging off
    set logging redirect on
    set logging on
end
define log_redirect_off
    set logging off
    set logging redirect off
    set logging on
end

define generate_printf_n
  log_redirect_on
  printf "\ndefine printf_n LF printf \"%%.%ds\", ($arg%d) LF end\n", ($arg0), 0
  log_redirect_off
  
  shell echo `tail -n 1 gdb.txt` | sed -r 's/LF/\n/g' > printf_n.txt

  log_redirect_on
  source printf_n.txt
  log_redirect_off
end

set logging file gdb.txt
set logging on

The 'source' command is guarded, so it won't disrupt normal output with a warning about re-definition of 'printf_n' function.


Now we have a dump_symbol function, which doesn't print garbage from beyond string limits. Good.

3. InlineTree structure

Now, let's find out the pointer to InlineTree object at the moment of the segfault:

Example 8. class Compile, source fragment

 // ... skipped ...
 private:
  // Fixed parameters to this compilation.
  const int             _compile_id;
  const bool            _save_argument_registers; // save/restore arg regs for trampolines
  const bool            _subsume_loads;         // Load can be matched as part of a larger op.
  const bool            _do_escape_analysis;    // Do escape analysis.
  ciMethod*             _method;                // The method being compiled.
  int                   _entry_bci;             // entry bci for osr methods.
  const TypeFunc*       _tf;                    // My kind of signature
  InlineTree*           _ilt;                   // Ditto (temporary).
  address               _stub_function;         // VM entry for stub being compiled, or NULL 
 // ... skipped ...

So, somewhere in the Compile object, not far away from ciMethod* of the method being compiled, lies InlineTree* pointer we are looking for.


Since we already know, how to obtain both Compile* and ciMethod* pointers, matching memory dump with object is easy:

Example 9. Finding out InlineTree* pointer

(gdb) f 14
#14 0xb6dcb5ff in Compile::Compile(ciEnv*, C2Compiler*, ciMethod*, int, bool, bool) () from .../libjvm.so

(gdb) p/x *(void**)($ebp+0x8)@7
$234 = {0xab41cb80, 0xab41d080,   0x88ee5c0,   0x8934e00,  0xffffffff,  0x1,  0x0}
    (Compile*)this      ciEnv*  C2Compiler*    ciMethod*          int  bool  bool

(gdb) p/x *0xab41cb80@10                       // look at Compile memory layout
$235 = {0x0, 0xab41cb80, 0x3, 0x100,           // some stuff (_compile_id, flags...)
        0x8934e00,                             // ciMethod* _method
        0xffffffff,                            // int _entry_bci
        0x890c4f0,                             // const TypeFunc* _tf
        0x8915640,                             // InlineTree* _ilt
        0x0, 0x0}                              // etc...


So, we have InlineTree* pointer now, let's see how we can print what's inside:

Example 10. class InlineTree source code (hotspot/src/share/vm/opto/parse.hpp, line 32)

class InlineTree : public ResourceObj {
  Compile*    C;                  // cache
  JVMState*   _caller_jvms;       // state of caller
  ciMethod*   _method;            // method being called by the caller_jvms
  InlineTree* _caller_tree;
  uint        _count_inline_bcs;  // Accumulated count of inlined bytecodes
  // ... skipped ...
  GrowableArray<InlineTree*> _subtrees;
  ...

Every InlineTree object holds ciMethod* which we can print by calling dump_cimethod gdb function.


And GrowableArray<InlineTree*> basically holds a pointer to an array of InlineTree* pointers:

Example 11. class GrowableArray source code (hotspot/src/share/vm/utilities/growableArray.hpp)

class GenericGrowableArray : public ResourceObj {
 protected:
  int    _len;          // current length
  int    _max;          // maximum length
  Arena* _arena;        // Indicates where allocation occurs:
                        //   0 means default ResourceArea

// ... skipped ...

template<class E> class GrowableArray : public GenericGrowableArray {
 private:
  E*     _data;         // data array


Now let's examine the memory layout of InlineTree object and define a function to print out method name:

Example 12. InlineTree* in memory

(gdb) p/x *0x8915640@10                      // InlineTree* _ilt
$239 = {0xab41cb80,                          // Compile* C (see, it's the value from above)
               0x0,                          // JVMState*
         0x8934e00,                          // ciMethod* _method  (offset 8)
               0x0,                          // InlineTree* _caller_tree (we don't care)
             0x2fd,                          // uint _count_inline_bcs
        0x3f800000,                          // const float _site_invoke_ratio (btw, it's 1.0f)
                                    // GenericGrowableArray class starts
               0x3,                          // int _len           (offset 24) 
               0x4,                          // int _max
               0x0,                          // Arena* _arena
                                    // GenericGrowableArray class ends
         0x8917808}                          // InlineTree** _data (offset 36)
(gdb)


Knowing all the offsets, creating function for dumping InlineTree::_method (without children) is easy:

Example 13. Non-recursive InlineTree dumping function

set $inlinetree_method_offset   = 8
set $inlinetree_len_offset      = 24 
set $inlinetree_children_offset = 36

define dump_ilt
    read_4 _method (($arg0)+$inlinetree_method_offset)
    dump_cimethod $_method
end

(gdb) dump_ilt 0x8915640
Test.previousSpaceIndex

// we can even get some child manually and print it:
(gdb) p/x *0x8917808@3
$321 = {0x8915930, 0x8917628, 0x89177d8}

(gdb) dump_ilt 0x8915930
java/io/PrintStream.print

(gdb) dump_ilt 0x8917628
java/lang/StringBuffer.charAt
(gdb)


4. Introducing stack

OK, we can now print a single InlineTree object, let's try to modify the function to call itself recursively to print all children, grandchildren, etc:

Example 14. First attempt on recursive InlineTree printing

define dump_inlinetree_recursive
    set $tree   = ($arg0)

    read_4 _method ($tree+$inlinetree_method_offset)
    dump_cimethod $_method

    read_4  _len ($tree+$inlinetree_len_offset)
    read_4 _base ($tree+$inlinetree_children_offset)

    set $i = 0
    while ($i<$_len)
        read_4 child $_base+($i*4)
        dump_inlinetree_recursive ($child)
        set $i = ($i+1)
    end
end
document dump_inlinetree_recursive
    Naive dump_inlinetree_recursive implementation, arg0 is InlineTree* address
end

Unfortunately, this doesn't work as expected. The reason is there is no local variables in gdb scripting language, and this implementation of course requires that variables are local (especially $i). If $i gets corrupted during inner dump_inlinetree_recursive call (and it is), we are doomed. Here is an example output:

(gdb) dump_inlinetree_recursive 0x8915640
Test.previousSpaceIndex
java/io/PrintStream.print
java/io/PrintStream.write
java/io/PrintStream.ensureOpen
(gdb) 

The output above is incorrect, as it prints InlineTree not completely - we've already seen that there should be at least one 'java/lang/StringBuffer.charAt' child of 'Test.previousSpaceIndex'.


The solution to this problem would be to explicitly manage the locality of variables. Using familiar gdb logging approach, we can introduce two stack management functions:

Example 15. Implementing push and pop functions

# pushes a variable to stack 
# arg0 - variable's name, arg1 - value
define push
    log_redirect_on
    p ($arg1)
    # gdb print has an output of a "$num = value" form, so grab it:
    shell echo set \$$arg0 = `tail -n 1 gdb.txt | sed -r 's/.* = (.*)/\1/'` >> stack
    log_redirect_off
end

# pops a variable from stack
define pop
     shell tail -n 1 stack > stack2
     source stack2
     shell sed -i '$d' stack
end

# prepare the stack (create external 'stack' file)
shell echo empty stack is empty > stack


Let's see these useful functions in action:

Example 16. Push/pop usage example

// push some vars to the stack
(gdb) push var1 42
(gdb) push var2 10
(gdb) push var1 20

// examine the stack
(gdb) shell cat stack
empty stack is empty
set $var1 = 42
set $var2 = 10
set $var1 = 20

// pop 2 vars and check the values
(gdb) pop
(gdb) p $var1
$634 = 20
(gdb) pop
(gdb) p $var2
$635 = 10

// stack now holds only the last var
(gdb) shell cat stack
empty stack is empty
set $var1 = 42

// pop the last var and check it's overwriten
(gdb) pop
(gdb) p $var1
$636 = 42
(gdb)


Finally, having push/pop functionality, implementing recursive traversal is trivial. Let's also add descent depth tracking and indent nodes appropriately:

Example 17. Final version of recursive InlineTree printing

# main wrapper/convenience function
define dump_inlinetree
    push dummy 0
    push dummy 0
    push dummy 0
    push dummy 0
    dump_inlinetree_internal $arg0 0
end
document dump_inlinetree
    Recursively dumps InlineTree* given as arg0
end

# actual implementation of recursive InlineTree* dumping
define dump_inlinetree_internal
    set $tree   = ($arg0)
    set $depth  = ($arg1)

    read_4 _method ($tree+$inlinetree_method_offset)

    # indent according to the current depth    
    printf "0x%lx:    ", $tree
    set $j = 0
    while ($j<$depth)
        printf "    "
        set $j = ($j+1)
    end
    
    dump_cimethod $_method

    read_4  _len ($tree+$inlinetree_len_offset)
    read_4 _base ($tree+$inlinetree_children_offset)

    set $i = 0
    while ($i<$_len)
        read_4 child $_base+($i*4)

        # store all locals on stack
        push depth $depth
        push i $i
        push _len  $_len 
        push _base $_base
        
        dump_inlinetree_internal ($child) ($depth+1)
        set $i = ($i+1)
    end

    # restore locals from stack before returning
    pop
    pop
    pop
    pop
end
document dump_inlinetree_internal
    Internal implementation of dump_inlinetree - use dump_inlinetree instead
end


And here is a complete InlineTree for our failing Java method:

(gdb) dump_inlinetree 0x8915640
0x8915640:    Test.previousSpaceIndex
0x8915930:        java/io/PrintStream.print
0x8915a48:            java/io/PrintStream.write
0x8915d30:                java/io/PrintStream.ensureOpen
0x8915e28:                java/io/Writer.write
0x8915ea0:                    java/lang/String.length
0x8915f18:                    java/io/BufferedWriter.write
0x8916240:                        java/io/BufferedWriter.ensureOpen
0x8916348:                        java/io/BufferedWriter.min
0x8916440:                        java/lang/String.getChars
0x8916728:                        java/io/BufferedWriter.flushBuffer
0x8916998:                            java/io/BufferedWriter.ensureOpen
0x8916b08:                java/io/BufferedWriter.flushBuffer
0x8916d40:                    java/io/BufferedWriter.ensureOpen
0x8916e38:                java/io/OutputStreamWriter.flushBuffer
0x8916eb8:                java/lang/String.indexOf
0x8916f50:                    java/lang/String.indexOf
0x8917628:        java/lang/StringBuffer.charAt
0x89177d8:        java/lang/StringBuffer.charAt
(gdb)

5. Conclusion

In this post, we have used code generation technique in gdb to improve symbolOop printing gdb function (and, eventually, ciMethod printing too). Also we have seen how one could implement stack-aware functions in pre-python gdb scripting language.

We have obtained an artificial core dump with a bigger InlineTree object, and tested our implementation on it.

Such an utility might prove itself useful in cases when JVM's server compiler fails in the middle of some huge method compilation, and the crash is hard to reproduce. That could happen as in large systems the compiler behaviour in terms of inlining is essentially indeterministic from the user's point of view. Too many factors affect compiler inlining decisions. However, if a single core dump exists, one can retrieve InlineTree information from it, and guide the compiler to take same inlining decisions, by using the hotspot's CompilerOracle interface (inline/dontinline commands). It can greatly improve reproducibility of the failure.

CompilerOracle usage is pretty straightforward:

$ java -XX:CompileCommand=help -version
  CompileCommand and the CompilerOracle allows simple control over
  what's allowed to be compiled.  The standard supported directives
  are exclude and compileonly.  The exclude directive stops a method
  from being compiled and compileonly excludes all methods except for
  the ones mentioned by compileonly directives.  The basic form of
  all commands is a command name followed by the name of the method
  in one of two forms: the standard class file format as in
  class/name.methodName or the PrintCompilation format
  class.name::methodName.  The method name can optionally be followed
  by a space then the signature of the method in the class file
  format.  Otherwise the directive applies to all methods with the
  same name and class regardless of signature.  Leading and trailing
  *'s in the class and/or method name allows a small amount of
  wildcarding.  

  Examples:

  exclude java/lang/StringBuffer.append
  compileonly java/lang/StringBuffer.toString ()Ljava/lang/String;
  exclude java/lang/String*.*
  exclude *.toString
java version "1.6.0_16"
Java(TM) SE Runtime Environment (build 1.6.0_16-b01)
Java HotSpot(TM) Client VM (build 14.2-b01, mixed mode, sharing)

Other commands are:

Example 18. Excerpt from hotspot/src/share/vm/compiler/compilerCommand.cpp, line 217

// this must parallel the enum OracleCommand
static const char * command_names[] = {
  "break",
  "print",
  "exclude",
  "inline",
  "dontinline",
  "compileonly",
  "log",
  "option",
  "quiet",
  "help"
};


1 comment:

  1. No comments?! Let me be the first ^_^
    By the way, great job!

    ReplyDelete

Google+ Badge