Bug 613824 - Missing and wrong hotspot.* probepoint arguments
Missing and wrong hotspot.* probepoint arguments
Status: CLOSED CURRENTRELEASE
Product: Red Hat Enterprise Linux 6
Classification: Red Hat
Component: java-1.6.0-openjdk (Show other bugs)
6.0
All Linux
low Severity medium
: rc
: ---
Assigned To: Deepak Bhole
BaseOS QE - Apps
Snapshot 10
:
Depends On:
Blocks: 616050 653998
  Show dependency treegraph
 
Reported: 2010-07-12 17:35 EDT by William Cohen
Modified: 2010-11-16 10:47 EST (History)
12 users (show)

See Also:
Fixed In Version: java-1.6.0-openjdk-1.6.0.0-1.21.b17.el6
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: 613822
: 616050 (view as bug list)
Environment:
Last Closed: 2010-11-10 15:42:58 EST
Type: ---
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)
try calculation of size in tapset, not source (1.85 KB, patch)
2010-07-28 18:08 EDT, Mark Wielaard
no flags Details | Diff
nmethod -E output (394.28 KB, application/x-bzip)
2010-07-29 04:27 EDT, Mark Wielaard
no flags Details

  None (edit)
Description William Cohen 2010-07-12 17:35:18 EDT
+++ This bug was initially created as a clone of Bug #613822 +++

Description of problem:

When attempting to use some of the variable avialable in the hotspot tapset found that some of the arguments were not available.

Version-Release number of selected component (if applicable):

systemtap-1.2-1.fc13.x86_64
java-1.6.0-openjdk-1.6.0.0-41.b18.fc13.x86_64
java-1.6.0-openjdk-devel-1.6.0.0-41.b18.fc13.x86_64
java-1.6.0-openjdk-debuginfo-1.6.0.0-41.b18.fc13.x86_64


How reproducible:

everytime

Steps to Reproduce:
1. Install  systemtap java-1.6.0-openjdk  java-1.6.0-openjdk-devel    java-1.6.0-openjdk-debuginfo
2. stap -L 'hotspot.*' > /dev/null
3. See the messages in the "actual results" section
  
Actual results:

semantic error: not accessible at this address (0x515136): identifier '$arg2' at /usr/share/systemtap/tapset/x86_64/hotspot.stp:438:32
        source:   class = user_string_n($arg1, $arg2);
                                               ^
semantic error: not accessible at this address (0x515136): identifier '$arg6' at :440:30
        source:   sig = user_string_n($arg5, $arg6);
                                             ^
semantic error: failed to retrieve location attribute for local 'arg8' (dieoffset: 0x3c5adc0): identifier '$arg8' at :442:10
        source:   size = $arg8;
                         ^
semantic error: not accessible at this address (0x5170b7): identifier '$arg2' at :456:32
        source:   class = user_string_n($arg1, $arg2);
                    

Expected results:

All the probe point arguments available in the hotspot tapset should be available. There shouldn't be any "semantic error" messages.


Additional info:

The probe hotspot.object_alloc has:

 size = $arg3;

that should be $arg4 for size according to http://java.sun.com/javase/6/docs/technotes/guides/vm/dtrace.html. However, when this is corrected get:

semantic error: not accessible at this address (0x59d460): identifier '$arg4' at :117:10
        source:   size = $arg4;
                         ^
Comment 1 William Cohen 2010-07-12 17:37:12 EDT
See a similar problem of missing $arg variables for hotspot probe points on RHEL-6 with the following rpms:

systemtap-1.2-9.el6.x86_64
java-1.6.0-openjdk-1.6.0.0-1.20.b17.el6.x86_64
java-1.6.0-openjdk-devel-1.6.0.0-1.20.b17.el6.x86_64
java-1.6.0-openjdk-debuginfo-1.6.0.0-1.20.b17.el6.x86_64

$ stap -L 'hotspot.*' > /dev/nullsemantic error: not accessible at this address (0x515036): identifier '$arg2' at /usr/share/systemtap/tapset/x86_64/hotspot.stp:438:32
        source:   class = user_string_n($arg1, $arg2);
                                               ^
semantic error: failed to retrieve location attribute for local 'arg8' (dieoffset: 0x3c5b7ce): identifier '$arg8' at :442:10
        source:   size = $arg8;
                         ^
semantic error: not accessible at this address (0x29156a): identifier '$arg4' at :236:32
        source:   class = user_string_n($arg3, $arg4);
                                               ^
semantic error: not accessible at this address (0x29156a): identifier '$arg6' at :237:33
        source:   method = user_string_n($arg5, $arg6);
                                                ^
semantic error: not accessible at this address (0x29183f): identifier '$arg4' at :254:32
        source:   class = user_string_n($arg3, $arg4);
                                               ^
semantic error: not accessible at this address (0x29183f): identifier '$arg6' at :255:33
        source:   method = user_string_n($arg5, $arg6);
                                                ^
semantic error: not accessible at this address (0x29183f): identifier '$arg8' at :256:30
        source:   sig = user_string_n($arg7, $arg8);
                                             ^
semantic error: not accessible at this address (0x59d4b0): identifier '$arg4' at :117:10
        source:   size = $arg4;
                         ^
Comment 3 RHEL Product and Program Management 2010-07-15 10:27:34 EDT
This issue has been proposed when we are only considering blocker
issues in the current Red Hat Enterprise Linux release. It has
been denied for the current Red Hat Enterprise Linux release.

** If you would still like this issue considered for the current
release, ask your support representative to file as a blocker on
your behalf. Otherwise ask that it be considered for the next
Red Hat Enterprise Linux release. **
Comment 4 Mark Wielaard 2010-07-19 06:27:35 EDT
The hotspot.object_alloc typo has a patch upstream and posted to the fedora bug report.

The "semantic error: failed to retrieve location attribute for local 'arg8'
(dieoffset: 0x3c5b7ce)" is because gcc did indeed did not output one in that case:

$ readelf --debug-dump=info /usr/lib/debug/usr/lib/jvm/java-1.6.0-openjdk-1.6.0.0.x86_64/jre/lib/amd64/server/libjvm.so.debug
 <4><3c5b7ce>: Abbrev Number: 171 (DW_TAG_variable)
    <3c5b7d0>   DW_AT_name        : (indirect string, offset: 0x11e0b9): arg8   
    <3c5b7d4>   DW_AT_decl_file   : 4   
    <3c5b7d5>   DW_AT_decl_line   : 1374        
    <3c5b7d7>   DW_AT_type        : <0x3c2e616> 

No DW_AT_location.

The not $argN is not accessible at this address errors are harder to spot where they come from. It should be noted that eu-readelf doesn't seem to like the .debug_loc section. Although readelf seems to parse it (with some warnings).

The error comes from dwarf_getlocation_addr () returning zero (which has the helpful comment /* Shouldn't happen.  */).

See for example through loc2c-test:

$ ./loc2c-test -e /usr/lib/debug/usr/lib/jvm/java-1.6.0-openjdk-1.6.0.0.x86_64/jre/lib/amd64/server/libjvm.so.debug 0x515036

        [3c5b6db] post_compiled_method_load_event (0x2e): 0x514fc0 (/usr/src/debug/icedtea6-1.7.3/openjdk/hotspot/src/share/vm/code/nmethod.cpp:1371) .. 0x515068 (/usr/src/debug/icedtea6-1.7.3/openjdk/hotspot/src/share/vm/code/nmethod.cpp:1384)
            this                          [3c5b6f7]     nmethod* const
            [3c5b706] <unnamed> (0xb)
                moop                          [3c5b70c] methodOop
                [3c5b745] <unnamed> (0xb): 0x514fdb (/usr/src/debug/icedtea6-1.7.3/openjdk/hotspot/src/share/vm/code/nmethod.cpp:1374) .. 0x515037 (/usr/src/debug/icedtea6-1.7.3/openjdk/hotspot/src/share/vm/code/nmethod.cpp:1383)
                    arg1                          [3c5b757]     jbyte*
                    arg2                          [3c5b768]     int
                    arg3                          [3c5b779]     jbyte*
                    arg4                          [3c5b78a]     int
                    arg5                          [3c5b79b]     jbyte*
                    arg6                          [3c5b7ac]     int
                    arg7                          [3c5b7bd]     address
                    arg8                          [3c5b7ce]     int

$ eu-readelf -N --debug-dump=info /usr/lib/debug/usr/lib/jvm/java-1.6.0-openjdk-1.6.0.0.x86_64/jre/lib/amd64/server/libjvm.so.debug

 [3c5b768]          variable
                   name                 (strp) "arg2"
                   decl_file            (data1) 4
                   decl_line            (data2) 1374
                   type                 (ref4) [3c2e616]
                   location             (data4) location list [ee657c]

$ readelf --debug-dump=loc /usr/lib/debug/usr/lib/jvm/java-1.6.0-openjdk-1.6.0.0.x86_64/jre/lib/amd64/server/libjvm.so.debug

    00ee657c 0000000000514fee 0000000000515027 (DW_OP_breg0: 16)
    00ee657c <End of list>

Will investigate further.
Comment 5 Mark Wielaard 2010-07-19 07:40:40 EDT
(In reply to comment #4)
> See for example through loc2c-test:
> 
> $ ./loc2c-test -e
> /usr/lib/jvm/java-1.6.0-openjdk-1.6.0.0.x86_64/jre/lib/amd64/server/libjvm.so
> 0x515036
> > [...]
> $ eu-readelf -N --debug-dump=info
> /usr/lib/debug/usr/lib/jvm/java-1.6.0-openjdk-1.6.0.0.x86_64/jre/lib/amd64/server/libjvm.so.debug
> 
>  [3c5b768]          variable
>                    name                 (strp) "arg2"
>                    decl_file            (data1) 4
>                    decl_line            (data2) 1374
>                    type                 (ref4) [3c2e616]
>                    location             (data4) location list [ee657c]
> 
> $ readelf --debug-dump=loc
> /usr/lib/debug/usr/lib/jvm/java-1.6.0-openjdk-1.6.0.0.x86_64/jre/lib/amd64/server/libjvm.so.debug
> 
>     00ee657c 0000000000514fee 0000000000515027 (DW_OP_breg0: 16)
>     00ee657c <End of list>
> 
> Will investigate further.    

That actually tells the story. We are looking for arg2 at address 0x515036, but we only got a location description for the addresses 0x514fee till 0x515027. So we are looking just beyond what the compiler can give us.

If we look at the other variables (arg1 and arg3) we see they do have location descriptions that are in scope for address 0x515036:

 [3c5b757]          variable
                   name                 (strp) "arg1"
                   decl_file            (data1) 4
                   decl_line            (data2) 1374
                   type                 (ref4) [3c2e9d3]
                   location             (data4) location list [ee651c]

    00ee651c 0000000000514fe9 0000000000514fed (DW_OP_breg0: 18; DW_OP_stack_value)
    00ee651c 0000000000514fed 0000000000515023 (DW_OP_breg13: 18; DW_OP_stack_value)
    00ee651c 0000000000515023 000000000051504f (DW_OP_reg13)
    00ee651c 0000000000515051 0000000000515067 (DW_OP_reg13)
    00ee651c <End of list>

 [3c5b779]          variable
                   name                 (strp) "arg3"
                   decl_file            (data1) 4
                   decl_line            (data2) 1374
                   type                 (ref4) [3c2e9d3]
                   location             (data4) location list [ee65a0]

    00ee65a0 0000000000515008 000000000051502b (DW_OP_breg4: 18; DW_OP_stack_value)
    00ee65a0 000000000051502b 000000000051505b (DW_OP_reg5)
    00ee65a0 <End of list>
Comment 6 Mark Wielaard 2010-07-19 10:08:51 EDT
The preprocessed (-E) method this happens in looks like:

void nmethod::post_compiled_method_load_event() {

  methodOop moop = method();
  do { __typeof__(((moop->klass_name()->bytes()))) arg1 = (moop->klass_name()->bytes()); __typeof__(((moop->klass_name()->utf8_length()))) arg2 = (moop->klass_name()->utf8_length()); __typeof__(((moop->name()->bytes()))) arg3 = (moop->name()->bytes()); __typeof__(((moop->name()->utf8_length()))) arg4 = (moop->name()->utf8_length()); __typeof__(((moop->signature()->bytes()))) arg5 = (moop->signature()->bytes()); __typeof__(((moop->signature()->utf8_length()))) arg6 = (moop->signature()->utf8_length()); __typeof__(((code_begin()))) arg7 = (code_begin()); __typeof__(((code_size()))) arg8 = (code_size()); ; __asm__ volatile (".section .probes," "\"aw\"" "\n" "\t.balign 8\n" "1:\n\t.asciz " "\"compiled__method__load\"" "\n" "\t.balign 4\n" "\t.int " "0x31425250" "\n" "\t.balign 8\n" "\t.quad " "1b\n" "\t.balign 8\n" "\t.quad " "2f" "\n" "\t.int 0\n" "\t.previous\n"); __asm__ volatile ("2:\n" "\tnop " "/* %0 %1 %2 %3 %4 %5 %6 %7 */" :: "g"(arg1), "g"(arg2), "g"(arg3), "g"(arg4), "g"(arg5), "g"(arg6), "g"(arg7), "g"(arg8)); } while (0)






                                ;

  if (JvmtiExport::should_post_compiled_method_load()) {
    JvmtiExport::post_compiled_method_load(this);
  }
}
Comment 7 Mark Wielaard 2010-07-19 10:13:44 EDT
Which generates the following assembly (-S):

.globl _ZN7nmethod31post_compiled_method_load_eventEv
        .type   _ZN7nmethod31post_compiled_method_load_eventEv, @function
_ZN7nmethod31post_compiled_method_load_eventEv:
.LFB14506:
        # /usr/local/build/icedtea6-obj/openjdk/hotspot/src/share/vm/code/nmethod.cpp:1429
        .loc 5 1429 0
        .cfi_startproc
.LVL460:
        # basic block 2
        pushq   %rbp    #
        .cfi_def_cfa_offset 16
        movq    %rsp, %rbp      #,
        .cfi_offset 6, -16
        .cfi_def_cfa_register 6
        movq    %rbx, -24(%rbp) #,
        movq    %r13, -8(%rbp)  #,
        movq    %rdi, %rbx      # this, this
        .cfi_offset 13, -24
        .cfi_offset 3, -40
.LVL461:
        movq    %r12, -16(%rbp) #,
        subq    $32, %rsp       #,
.LBB4617:
.LBB4618:
.LBB4619:
        # /usr/local/build/icedtea6-obj/openjdk/hotspot/src/share/vm/code/nmethod.hpp:321
        .loc 4 321 0
        movq    72(%rdi), %r12  # <variable>._method, moop
        .cfi_offset 12, -32
.LVL462:
.LBE4619:
.LBE4618:
.LBB4620:
        # /usr/local/build/icedtea6-obj/openjdk/hotspot/src/share/vm/code/nmethod.cpp:1432
        .loc 5 1432 0
        movq    %r12, %rdi      # moop,
.LVL463:
        call    _ZNK13methodOopDesc10klass_nameEv@PLT   #
.LVL464:
        movq    %r12, %rdi      # moop,
        movq    %rax, %r13      #, D.157337
.LVL465:
        call    _ZNK13methodOopDesc10klass_nameEv@PLT   #
.LVL466:
.LBB4621:
.LBB4622:
.LBB4634:
.LBB4635:
.LBB4636:
        .file 24 "/usr/local/build/icedtea6-obj/openjdk/hotspot/src/share/vm/oops/methodOop.hpp"
        # /usr/local/build/icedtea6-obj/openjdk/hotspot/src/share/vm/oops/methodOop.hpp:137
        .loc 24 137 0
        movq    16(%r12), %rcx  # <variable>._constMethod, D.165475
.LVL467:
.LBE4636:
.LBE4635:
.LBE4634:
.LBB4623:
.LBB4624:
.LBB4625:
.LBB4626:
.LBB4627:
.LBB4628:
        .file 25 "/usr/local/build/icedtea6-obj/openjdk/hotspot/src/share/vm/oops/constantPoolOop.hpp"
        # /usr/local/build/icedtea6-obj/openjdk/hotspot/src/share/vm/oops/constantPoolOop.hpp:73
        .loc 25 73 0
        movq    24(%r12), %rdx  # <variable>._constants, <variable>._constants
.LBE4628:
.LBE4627:
        # /usr/local/build/icedtea6-obj/openjdk/hotspot/src/share/vm/oops/constantPoolOop.hpp:297
        .loc 25 297 0
        movzwl  64(%rcx), %esi  # <variable>._name_index, <variable>._name_index
.LBE4626:
.LBE4625:
.LBE4624:
.LBE4623:
.LBE4622:
.LBE4621:
.LBB4639:
.LBB4640:
.LBB4641:
.LBB4642:
.LBB4643:
        movzwl  66(%rcx), %ecx  # <variable>._signature_index, <variable>._signature_index
.LBE4643:
.LBE4642:
.LBE4641:
.LBE4640:
.LBE4639:
.LBB4646:
.LBB4638:
.LBB4637:
.LBB4633:
.LBB4632:
.LBB4631:
.LBB4630:
.LBB4629:
        # /usr/local/build/icedtea6-obj/openjdk/hotspot/src/share/vm/oops/constantPoolOop.hpp:73
        .loc 25 73 0
        addq    $56, %rdx       #, D.165473
.LBE4629:
.LBE4630:
.LBE4631:
.LBE4632:
        # /usr/local/build/icedtea6-obj/openjdk/hotspot/src/share/vm/oops/constantPoolOop.hpp:297
        .loc 25 297 0
        movq    (%rdx,%rsi,8), %rsi     #* D.165473, D.165466
.LVL468:
.LBE4633:
.LBE4637:
.LBE4638:
.LBE4646:
.LBB4647:
.LBB4645:
.LBB4644:
        movq    (%rdx,%rcx,8), %rcx     #* D.165473, D.165511
.LVL469:
.LBE4644:
.LBE4645:
.LBE4647:
.LBB4648:
.LBB4649:
        # /usr/local/build/icedtea6-obj/openjdk/hotspot/src/share/vm/code/nmethod.hpp:340
        .loc 4 340 0
        movq    184(%rbx), %rdx # <variable>._entry_point, arg7
.LVL470:
.LBE4649:
.LBE4648:
        # /usr/local/build/icedtea6-obj/openjdk/hotspot/src/share/vm/code/nmethod.cpp:1432
        .loc 5 1432 0
#APP
# 1432 "/usr/local/build/icedtea6-obj/openjdk/hotspot/src/share/vm/code/nmethod.cpp" 1
        .section .probes,"aw"
        .balign 8
1:
        .asciz "compiled__method__load"
        .balign 4
        .int 0x31425250
        .balign 8
        .quad 1b
        .balign 8
        .quad 2f
        .int 0
        .previous

# 0 "" 2
#NO_APP
.LBB4650:
.LBB4651:
.LBB4652:
.LBB4653:
        movslq  140(%rbx), %r9  # <variable>._stub_offset, <variable>._stub_offset
.LBE4653:
.LBE4652:
.LBE4651:
.LBE4650:
        leaq    18(%rsi), %rdi  #, tmp74
        leaq    18(%rcx), %r8   #, tmp76
        addq    $18, %r13       #, tmp72
.LVL471:
.LBB4657:
.LBB4658:
        movzwl  16(%rax), %eax  # <variable>._length, <variable>._length
.LVL472:
.LBE4658:
.LBE4657:
.LBB4659:
.LBB4660:
        movzwl  16(%rsi), %esi  # <variable>._length, <variable>._length
.LVL473:
.LBE4660:
.LBE4659:
.LBB4661:
.LBB4662:
        movzwl  16(%rcx), %ecx  # <variable>._length, <variable>._length
.LVL474:
.LBE4662:
.LBE4661:
.LBB4663:
.LBB4656:
.LBB4655:
.LBB4654:
        leaq    (%rbx,%r9), %r9 #, tmp80
.LBE4654:
.LBE4655:
        subl    %edx, %r9d      # arg7, tmp81
.LBE4656:
.LBE4663:
#APP
# 1432 "/usr/local/build/icedtea6-obj/openjdk/hotspot/src/share/vm/code/nmethod.cpp" 1
        2:
        nop /* %r13 %eax %rdi %esi %r8 %ecx %rdx %r9d */        # tmp72, <variable>._length, tmp74, <variable>._length, tmp76, <variable>._length, arg7, tmp81
# 0 "" 2
#NO_APP
.LBE4620:
        # /usr/local/build/icedtea6-obj/openjdk/hotspot/src/share/vm/code/nmethod.cpp:1441
        .loc 5 1441 0
        movq    _ZN11JvmtiExport33_should_post_compiled_method_loadE@GOTPCREL(%rip), %rax       #, tmp82
        cmpb    $0, (%rax)      # _should_post_compiled_method_load
        jne     .L341   #,
        # basic block 3
.LBE4617:
        # /usr/local/build/icedtea6-obj/openjdk/hotspot/src/share/vm/code/nmethod.cpp:1444
        .loc 5 1444 0
        movq    -24(%rbp), %rbx #,
.LVL475:
        movq    -16(%rbp), %r12 #,
.LVL476:
        movq    -8(%rbp), %r13  #,
.LVL477:
        leave
        .cfi_remember_state
        .cfi_def_cfa 7, 8
        ret
.LVL478:
        .p2align 4,,10
        .p2align 3
.L341:
        # basic block 4
        .cfi_restore_state
.LBB4664:
        # /usr/local/build/icedtea6-obj/openjdk/hotspot/src/share/vm/code/nmethod.cpp:1442
        .loc 5 1442 0
        movq    %rbx, %rdi      # this,
.LVL479:
.LBE4664:
        # /usr/local/build/icedtea6-obj/openjdk/hotspot/src/share/vm/code/nmethod.cpp:1444
        .loc 5 1444 0
        movq    -16(%rbp), %r12 #,
.LVL480:
        movq    -24(%rbp), %rbx #,
.LVL481:
        movq    -8(%rbp), %r13  #,
.LVL482:
        leave
        .cfi_def_cfa 7, 8
.LBB4665:
        # /usr/local/build/icedtea6-obj/openjdk/hotspot/src/share/vm/code/nmethod.cpp:1442
        .loc 5 1442 0
        jmp     _ZN11JvmtiExport25post_compiled_method_loadEP7nmethod@PLT       #
.LBE4665:
        .cfi_endproc
.LFE14506:
        .size   _ZN7nmethod31post_compiled_method_load_eventEv, .-_ZN7nmethod31post_compiled_method_load_eventEv
Comment 8 Mark Wielaard 2010-07-19 10:34:43 EDT
I split this bug in two.

This bug (#613824) should now be tracking the "wrong argument" issue. For which there is an upstream patch, see https://bugzilla.redhat.com/show_bug.cgi?id=613822#c2

There is now a separate bug #616050 to track the missing/partial location expressions generated by gcc.
Comment 9 Frank Ch. Eigler 2010-07-20 10:27:44 EDT
Should require only an unpatched rebuild, once gcc is fixed.
Comment 11 Mark Wielaard 2010-07-20 13:40:40 EDT
For QA, the original test in the description is a good one:
$ stap -L 'hotspot.*'
should not give any semantic errors.
Comment 14 Jakub Jelinek 2010-07-28 10:37:07 EDT
On which architecture is that, can you attach preprocessed sources on which arg4 isn't available, together with gcc options used to compile it?

Thanks.
Comment 21 Jakub Jelinek 2010-07-28 15:34:21 EDT
Actually, I have a short testcase now, thanks for help:

void
foo (int i)
{
  int q = i * 8;
  asm volatile ("/* %0 */" : : "g" (q));
}
Comment 22 Mark Wielaard 2010-07-28 15:42:49 EDT
Replicated the issue on i686 with a local build of icedtea6:

$ /usr/local/install/systemtap/bin/stap -p4 -e 'probe
process("openjdk.build/j2sdk-image/jre/lib/i386/server/libjvm.so").mark("object__alloc")
{ log($arg4) }'
semantic error: not accessible at this address (0x52f297, dieoffset:
0x6859154): identifier '$arg4' at <input>:1:102
        source: probe
process("openjdk.build/j2sdk-image/jre/lib/i386/server/libjvm.so").mark("object__alloc")
{ log($arg4) }
                                                                               
                                     ^

 [6859154]          variable
                   name                 (strp) "arg4"
                   decl_file            (data1) 2
                   decl_line            (data2) 713
                   type                 (ref4) [681aebb]
                   location             (data4) location list [a42577]

    00a42577 0052f288 0052f28b (DW_OP_breg7: 0; DW_OP_lit2; DW_OP_shl;
DW_OP_stack_value)
    00a42577 <End of list>

So, indeed the location list doesn't cover the probe address.

Trying to get the -save-temps output now. [Actually - mid air collision with comment #21. So not doing that, since that would be way bigger than that simple reproducer]
Comment 24 Jakub Jelinek 2010-07-28 16:11:20 EDT
And there are two issues that together cause this.
TER substitutes more complex expressions into the asm, so we end up with:
  # DEBUG q => i * 8
  __asm__ __volatile__("/* %0 */" :  : "g" i * 8);
and both i * 8 expressions are expanded separately.  In 4.5+ this doesn't show up in *.optimized dump, but still that's what it does during expansion.
And, the second problem is that the debug insn uses MULT by 8, but expansion chooses to use SHL by 3.  So we have in *expand:

(debug_insn 6 5 7 3 u.c:4 (var_location:SI q (mult:SI (reg/v:SI 58 [ i ])
        (const_int 8 [0x8]))) -1 (nil))

(insn 7 6 8 3 u.c:5 (parallel [
            (set (reg:SI 59)
                (ashift:SI (reg/v:SI 58 [ i ])
                    (const_int 3 [0x3])))
            (clobber (reg:CC 17 flags))
        ]) -1 (nil))

(insn 8 7 13 3 u.c:5 (parallel [
            (asm_operands/v ("/* %0 */") ("") 0 [
                    (reg:SI 59)
                ]
                 [
                    (asm_input:SI ("g") (null):0)
                ]
                 [] u.c:6)
            (clobber (reg:QI 18 fpsr))
            (clobber (reg:QI 17 flags))
        ]) -1 (nil))

(both 4.4 and trunk).  The problem is that CSELIB doesn't use the same hash for (mult:SI (reg:SI 58) (const_int 8)) and (ashift:SI (reg:SI 58) (const_int 3)) and as multiplication isn't reversible operation and i isn't live anywhere any longer, says that q is optimized away after insn 7 during var-tracking.

Sure, we could teach cselib.c to use the same hash for such simple multiplications by constant vs. shifts (and similarly for divides), but it can't ever handle everything.  Say if the testcase is
void
foo (int i)
{
  int q = i * 17;
  asm volatile ("/* %0 */" : : "g" (q));
}
instead, we get:
        movl    %edi, %eax
        sall    $4, %eax
        leal    (%rax,%rdi), %edi
and again, the original %edi isn't available anywhere (so can't multiply it by 17) and cselib won't easily find out this is equivalent.

(debug_insn 6 3 19 2 u.c:4 (var_location:SI q (mult:SI (reg/v:SI 5 di [orig:58 i ] [58])
        (const_int 17 [0x11]))) -1 (nil))

(insn:TI 19 6 8 2 u.c:5 (set (reg:SI 0 ax [60])
        (reg/v:SI 5 di [orig:58 i ] [58])) 47 {*movsi_1} (nil))

(insn:TI 8 19 20 2 u.c:5 (parallel [
            (set (reg:SI 0 ax [60])
                (ashift:SI (reg:SI 0 ax [60])
                    (const_int 4 [0x4])))
            (clobber (reg:CC 17 flags))
        ]) 495 {*ashlsi3_1} (expr_list:REG_UNUSED (reg:CC 17 flags)
        (expr_list:REG_EQUAL (ashift:SI (reg/v:SI 5 di [orig:58 i ] [58])
                (const_int 4 [0x4]))
            (nil))))

(insn:TI 20 8 10 2 u.c:5 (set (reg:SI 5 di [61])
        (subreg:SI (plus:DI (reg:DI 0 ax [60])
                (reg:DI 5 di [orig:58 i ] [58])) 0)) 271 {*lea_1_rex64} (expr_list:REG_DEAD (reg:DI 0 ax [60])
        (nil)))

(insn:TI 10 20 25 2 u.c:5 (parallel [
            (asm_operands/v ("/* %0 */") ("") 0 [
                    (reg:SI 5 di [61])
                ]
                 [
                    (asm_input:SI ("g") (null):0)
                ]
                 [] u.c:6)
            (clobber (reg:QI 18 fpsr))
            (clobber (reg:QI 17 flags))
        ]) -1 (expr_list:REG_DEAD (reg:SI 5 di [61])
        (expr_list:REG_UNUSED (reg:QI 18 fpsr)
            (expr_list:REG_UNUSED (reg:QI 17 flags)
                (nil)))))

We could have some systemtap specific hack in gcc, which for inline asms would compare expressions TERed into operands with immediately preceeding debug insns
and add those again right before the asm_operands insn mentioning pseudos actually used by the operands... Except that sys/sdt.h doesn't use one inline asm, but two, so there are no immediately preceeding debug insns (and in theory, between the debug insns could be real code too).

So, this simple case of * 8 multiplication is in theory solvable quite easily, but it can get much harder very quickly.  In openjdk you could perhaps avoid doing that multiplication, and if the constant is really always constant, just put it into the stp script instead and multiply there, or use 2 arguments instead of one.
Comment 26 Jakub Jelinek 2010-07-28 17:58:51 EDT
I think a patch like:
--- tapset/hotspot.stp  2010-07-28 18:09:29.875103493 -0400
+++ tapset/hotspot.stp  2010-07-28 21:54:35.721334118 -0400
@@ -120,7 +120,7 @@ probe hotspot.object_alloc =
   name = "object_alloc";
   thread_id = $arg1;
   class = user_string_n($arg2, $arg3);
-  size = $arg4;
+  size = $arg4 * $HeapWordSize;
   probestr = sprintf("%s(thread_id=%d,class='%s',size=0x%x)",
                      name, thread_id, class, size);
 }
--- openjdk/hotspot/src/share/vm/runtime/sharedRuntime.cpp      2010-07-28 18:09:56.083112803 -0400
+++ openjdk/hotspot/src/share/vm/runtime/sharedRuntime.cpp      2010-07-28 21:55:33.177080038 -0400
@@ -749,7 +749,7 @@ int SharedRuntime::dtrace_object_alloc_b
   int size = o->size();
   symbolOop name = klass->name();
   HS_DTRACE_PROBE4(hotspot, object__alloc, get_java_tid(thread),
-                   name->bytes(), name->utf8_length(), size * HeapWordSize);
+                   name->bytes(), name->utf8_length(), size);
   return 0;
 }
 

could fix workaround this issue, HeapWordSize is available with its DW_AT_const_value in debug info and when it doesn't multiply at runtime, the above described issue won't happen on the code.  Additionally, it will be one instruction shorter at runtime.  Of course this needs testing...
Comment 27 Mark Wielaard 2010-07-28 18:08:36 EDT
Created attachment 435138 [details]
try calculation of size in tapset, not source

I had the same idea as the one from comment #24. We are already using $HeapWordSize in jstack.stp, so this should work. This is what I am currently building (against upstream icedtea6 on fedora 13 i686, gcc-4.4.4-13.fc13.i686). But won't know the results till tomorrow morning (slow laptop).
Comment 28 Deepak Bhole 2010-07-28 19:01:34 EDT
The patch in comment# 27 fixes the issue. Thanks. I will do a build tomorrow.
Comment 29 Mark Wielaard 2010-07-29 04:08:45 EDT
So the good news is that the workaround patch for hotspot.object_alloc. SystemTap fetches the $HeapWordSize correctly, making the size correct.

But I am seeing part of the original issue (this might be i386/fedora gcc-4.4.4-13.fc13.i686 specific, not tested on rhel):

$ /usr/local/install/systemtap/bin/stap -I openjdk.build/j2sdk-image/tapset -L 'hotspot.*'
semantic error: not accessible at this address (0x2c3e38, dieoffset: 0x415f1db): identifier '$arg2' at openjdk.build/j2sdk-image/tapset/hotspot.stp:463:32
        source:   class = user_string_n($arg1, $arg2);
                                               ^
semantic error: not accessible at this address (0x4ad7e8, dieoffset: 0x54dabcf): identifier '$arg2' at :463:32
        source:   class = user_string_n($arg1, $arg2);
                                               ^
semantic error: not accessible at this address (0x4ad7e8, dieoffset: 0x54dac13): identifier '$arg6' at :465:30
        source:   sig = user_string_n($arg5, $arg6);
                                             ^

These come from hotspot.compiled_method_load:

  name = "compiled_method_load";
  class = user_string_n($arg1, $arg2);
  method = user_string_n($arg3, $arg4);
  sig = user_string_n($arg5, $arg6);
  code = $arg7;
  size = $arg8;


semantic error: not accessible at this address (0x4b0933, dieoffset: 0x54e05ab): identifier '$arg2' at :482:32
        source:   class = user_string_n($arg1, $arg2);
                                               ^
semantic error: not accessible at this address (0x4b0933, dieoffset: 0x54e05bf): identifier '$arg4' at :483:33
        source:   method = user_string_n($arg3, $arg4);
                                                ^

And these from hotspot.compiled_method_unload:

  name = "compiled_method_unload";
  class = user_string_n($arg1, $arg2);
  method = user_string_n($arg3, $arg4);
  sig = user_string_n($arg5, $arg6);

Both come from nmethod.cpp:

void nmethod::post_compiled_method_load_event() {

  methodOop moop = method();
  HS_DTRACE_PROBE8(hotspot, compiled__method__load,
      moop->klass_name()->bytes(),
      moop->klass_name()->utf8_length(),
      moop->name()->bytes(),
      moop->name()->utf8_length(),
      moop->signature()->bytes(),
      moop->signature()->utf8_length(),
      code_begin(), code_size());

  if (JvmtiExport::should_post_compiled_method_load()) {
    JvmtiExport::post_compiled_method_load(this);
  }
}

The unload event is embedded in multiple places:

#define DTRACE_METHOD_UNLOAD_PROBE(method)                                \
  {                                                                       \
    methodOop m = (method);                                               \
    if (m != NULL) {                                                      \
      symbolOop klass_name = m->klass_name();                             \
      symbolOop name = m->name();                                         \
      symbolOop signature = m->signature();                               \
      HS_DTRACE_PROBE6(hotspot, compiled__method__unload,                 \
        klass_name->bytes(), klass_name->utf8_length(),                   \
        name->bytes(), name->utf8_length(),                               \
        signature->bytes(), signature->utf8_length());                    \
    }                                                                     \
  }

Will attach the preprocessed source for nmethod.cpp
Comment 30 Mark Wielaard 2010-07-29 04:27:26 EDT
Created attachment 435220 [details]
nmethod -E output

g++ -DLINUX -D_GNU_SOURCE -DIA32 -DPRODUCT -I. -I../generated/adfiles -I../generated/jvmtifiles -I/home/mark/src/icedtea6-obj/openjdk/hotspot/src/share/vm/asm -I/home/mark/src/icedtea6-obj/openjdk/hotspot/src/share/vm/c1 -I/home/mark/src/icedtea6-obj/openjdk/hotspot/src/share/vm/ci -I/home/mark/src/icedtea6-obj/openjdk/hotspot/src/share/vm/classfile -I/home/mark/src/icedtea6-obj/openjdk/hotspot/src/share/vm/code -I/home/mark/src/icedtea6-obj/openjdk/hotspot/src/share/vm/compiler -I/home/mark/src/icedtea6-obj/openjdk/hotspot/src/share/vm/gc_implementation -I/home/mark/src/icedtea6-obj/openjdk/hotspot/src/share/vm/gc_implementation/shared -I/home/mark/src/icedtea6-obj/openjdk/hotspot/src/share/vm/gc_implementation/parallelScavenge -I/home/mark/src/icedtea6-obj/openjdk/hotspot/src/share/vm/gc_implementation/g1 -I/home/mark/src/icedtea6-obj/openjdk/hotspot/src/share/vm/gc_implementation/concurrentMarkSweep -I/home/mark/src/icedtea6-obj/openjdk/hotspot/src/share/vm/gc_implementation/parNew -I/home/mark/src/icedtea6-obj/openjdk/hotspot/src/share/vm/gc_interface -I/home/mark/src/icedtea6-obj/openjdk/hotspot/src/share/vm/interpreter -I/home/mark/src/icedtea6-obj/openjdk/hotspot/src/share/vm/libadt -I/home/mark/src/icedtea6-obj/openjdk/hotspot/src/share/vm/memory -I/home/mark/src/icedtea6-obj/openjdk/hotspot/src/share/vm/oops -I/home/mark/src/icedtea6-obj/openjdk/hotspot/src/share/vm/opto -I/home/mark/src/icedtea6-obj/openjdk/hotspot/src/share/vm/prims -I/home/mark/src/icedtea6-obj/openjdk/hotspot/src/share/vm/runtime -I/home/mark/src/icedtea6-obj/openjdk/hotspot/src/share/vm/services -I/home/mark/src/icedtea6-obj/openjdk/hotspot/src/share/vm/shark -I/home/mark/src/icedtea6-obj/openjdk/hotspot/src/share/vm/utilities -I/home/mark/src/icedtea6-obj/openjdk/hotspot/src/cpu/x86/vm -I/home/mark/src/icedtea6-obj/openjdk/hotspot/src/os/linux/vm -I/home/mark/src/icedtea6-obj/openjdk/hotspot/src/os_cpu/linux_x86/vm -I../generated -DHOTSPOT_RELEASE_VERSION="\"17.0-b16\"" -DHOTSPOT_BUILD_TARGET="\"product\"" -DHOTSPOT_BUILD_USER="\"mark\"" -DHOTSPOT_LIB_ARCH=\"i386\" -DJRE_RELEASE_VERSION="\"1.6.0_20-b20\"" -DHOTSPOT_VM_DISTRO="\"OpenJDK\"" -DDERIVATIVE_ID="\"IcedTea6 1.9pre+rdd4d9f50ac7c\"" -DDISTRIBUTION_ID="\"Built on Fedora release 13 (Goddard) (Wed Jul 28 23:02:02 CEST 2010)\"" -DCOMPILER2 -DCOMPILER1 -fpic -fno-rtti -fno-exceptions -D_REENTRANT -fcheck-new -m32 -march=i586 -pipe -g -O3 -fno-strict-aliasing -DVM_LITTLE_ENDIAN -Werror -Wpointer-arith -Wsign-compare    -DDTRACE_ENABLED -c -E -o nmethod.E /home/mark/src/icedtea6-obj/openjdk/hotspot/src/share/vm/code/nmethod.cpp
Comment 31 Jakub Jelinek 2010-07-29 06:20:50 EDT
Ah, i?86, so far I've been looking at x86-64.  Will look at this.
Comment 32 Jakub Jelinek 2010-07-29 08:53:03 EDT
Distilled testcase for -fpic -m32 -march=i586 -g -O2:

struct S1 { void *p, *q; unsigned short s; char t[1]; };
struct S2 { void *p; char q[0x24]; unsigned short s; unsigned short t; };
struct S3 { void *p; void *q; struct S2 *s; char *t; };
struct S4 { char p[0x34]; struct S3 *s; char q[0x24]; int t; char r[0x28]; char *u; };
void bar (struct S4 *this);
struct S1 *baz (struct S3 *);
int v;

void
foo (struct S4 *x)
{
  struct S3 *m = x->s;
  char *var1 = &baz (m)->t[0];
  int var2 = baz (m)->s;
  char *var3 = &(*(struct S1 **)(m->t + 36 + m->s->s * 4))->t[0];
  int var4 = (*(struct S1 **)(m->t + 36 + m->s->s * 4))->s;
  char *var5 = &(*(struct S1 **)(m->t + 36 + m->s->t * 4))->t[0];
  int var6 = (*(struct S1 **)(m->t + 36 + m->s->t * 4))->s;
  char *var7 = x->u;
  int var8 = ((char *)x + x->t) - var7;
  asm volatile ("");
  asm volatile ("/* %0 %1 %2 %3 %4 %5 %6 %7 */"
		: : "g" (var1), "g" (var2), "g" (var3), "g" (var4),
		    "g" (var5), "g" (var6), "g" (var7), "g" (var8));
  if (v)
    bar (x);
}
Comment 33 Jakub Jelinek 2010-07-29 17:10:56 EDT
Ok, so there are two issues with this testcase:

1) one 4.4 and earlier specific - only 4.5+ uses alias oracle to disambiguate
   in *true_dependence and so store to (mem:SI (...) %sfp-8) invalidates various
   MEMs from the cselib hash table.  As %sfp (spill slots) aren't addressable,
   in 4.5+ rtx_refs_may_alias_p will say the two mems can't alias if
   one is %sfp and the other is not.  While obviously backporting all the
   aliasing changes is out of the question, perhaps we could consider just
   special casing this %sfp vs. non-%sfp if MEM_EXPR, MEM_OFFSET and MEM_SIZE is 
   present on both MEMs.  Either it could be done at the end of
   true_dependence/canon_true_dependence (most risky), or e.g. in a new
   cselib_canon_true_dependence which would do the same as canon_true_dependence,
   just do this extra disambiguation and call it only from cselib, only only from 
   cselib when used in var-tracking.
2) the other issue is similar to the * 8 issue discussed on x86-64 earlier.
   This time it is (zero_extend:SI (something:HI)) vs.
   (and:SI (something:SI) (const_int 0xffff)) which again would need to be hashed
   using the same hash and compared equal in cselib.
Comment 34 Deepak Bhole 2010-07-30 13:37:08 EDT
Fixed in java-1.6.0-openjdk-1.6.0.0-1.21.b17.el6
Comment 35 William Cohen 2010-07-30 14:37:22 EDT
I have installed the rpms from this build.  The following smoke test that originally demonstrated this problem works:

[wcohen@cannondale java]$ stap -L 'hotspot.*' > /dev/null
[wcohen@cannondale java]$ 


The JObjectStats example on the following URL provide much more reasonable:

http://icedtea.classpath.org/~vanaltj/stapexamples/
Comment 38 releng-rhel@redhat.com 2010-11-10 15:42:58 EST
Red Hat Enterprise Linux 6.0 is now available and should resolve
the problem described in this bug report. This report is therefore being closed
with a resolution of CURRENTRELEASE. You may reopen this bug report if the
solution does not work for you.

Note You need to log in before you can comment on or make changes to this bug.