» Sign in
  


 

NOTE: tusc is an HP "as is" product, and is not currently supported by HP's IT Resource Center.

tusc works with HP-UX 11.0 and 11i PA-RISC systems, and HP-UX 11i HP Integrity systems. It is not supported on HP-UX 10.20. tusc is similar in functionality to truss on Solaris.

tusc is a great program for working with Java™.  It gives you another view into the system activity in addition to Java stack traces, GlancePlus, and HPjmeter. tusc has many options which can be displayed with the command tusc -help. For example, you can use  -l and -T "" to get a timestamp. Man pages are available in the tusc.shar file.

Below you'll find a list of the available options, plus a few examples of using tusc for debugging and performance tuning.

Download the tusc.shar file.

Usage

Below is the output from tusc -help:

Usage: tusc [-<options>] <command [args ...]> -OR- <pid [pid ...]>
        -a: show exec arguments
        -A: append to output file
        -b bsize: dump 'bsize' max bytes (-r/-w)
        -c: count syscalls instead of printing trace
        -d [+][!][fd | all]: select only syscalls using fd
        -e: show environment variables
        -E: show syscall entries
        -f: follow forks
        -F: show kernel's ttrace feature level
        -g: don't attach to members of my session
        -h: show state of all processes when idle
        -i: don't display interruptible syscalls
        -I start[/stop]: single-step and show instructions
        -k: keep alive (wait for *all* processes)
        -l: print lwpids
        -n: print process names
        -o [file|fd]: send trace output to file or fd
        -p: print pids
        -Q: be quiet about some warnings
        -r [!][fd | all]: dump read buffers
        -R: show syscall restarts
        -s [!]syscalls: [un]select these syscalls
        -S [!]signals: [un]select these signals
        -t: detach process if it becomes traced
        -T timestamp: print time stamps
        -u: print user thread IDs (pthreads)
        -v: verbose (some system calls only)
        -V: print version
        -w [!][fd | all]: dump write buffers
        -x: print raw (hex) arguments
        -z: only show failing syscalls

Here are a few examples of debugging and performance tuning information you can see with tusc.

thread.interrupt

The Thread.interrupt() call is implemented using SIGUSR1. Hence, if you see SIGUSR1 in the tusc output, the program must be making Thread.interrupt() calls. You can confirm this by making an -Xeprof trace and viewing the data with HPjmeter. It's not necessarily good or bad to use Thread.interrupt(), but you can monitor it with tusc and it may be helpful information in various performace or correctness situations. Here is an example of a Thread.interrupt(). Threads are indentified by their lwp id, shown in the second column. Thread 19729 interrupts thread 19731 with the signal.

1008628500.571138 {19731} write(1, "\n", 1) ...................... = 1
1008628500.571337 {19731} gettimeofday(0x6c258910, NULL) ......... = 0
1008628500.571444 {19731} clock_gettime(CLOCK_REALTIME, 0x6c258a40) = 0
1008628500.571625 {19729} _lwp_kill(19731, SIGUSR1) .............. = 0
1008628500.571737 {19731}   Received signal 16, SIGUSR1, in ksleep(), \ 
    91;caught]
1008628500.571757 {19731}     Siginfo: sent by pid 10468 (uid 565), \ 
    si_errno: 0
1008628500.571939 {19731} ksleep(PTH_CONDVAR_OBJECT, 0x1fde70, 0x1fde78, \ 
    0x6c258908) = -EINTR
1008628500.572143 {19731} gettimeofday(0x6c258910, NULL) ......... = 0
1008628500.572258 {19801} ksleep(PTH_MUTEX_OBJECT, 0xaae8, 0xaaf0, \ 
    NULL) = 0
1008628500.572438 {19731} clock_gettime(CLOCK_REALTIME, 0x6c258a40) = 0
1008628500.572522 {19801} kwakeup(PTH_CONDVAR_OBJECT, 0x309580, \ 
    WAKEUP_ALL, 0x6b6c1848) = 0
1008628500.572611 {19802} ksleep(PTH_CONDVAR_OBJECT, 0x309580, 0x309588, \ 
    0x6b640908) = 0
1008628500.572704 {19729} kwakeup(PTH_MUTEX_OBJECT, 0xaae8, WAKEUP_ONE, \ 
    0x6c2d978c) = 0
1008628500.572800 {19778} sched_yield() .......................... = 0

Here we used -T "" and -l to show the timestamp in basic format and the lwp id. This time we happened to interrupt a thread sleeping on a pthread_cond_wait call. You can see how he wakes up with EINTR. This will cause an InterruptedException in the Java program.

Implicit null pointer checks

The hotspot compiled code uses SIGSEGV and SIGBUS to implement implicit null pointer checks which result in NullPointerExceptions in the Java application, for example, when trying to perform a method dispatch when the "this" pointer is null. To a Java programmer, it's not particularly important whether the exceptions come from interpreted or compiled code, but it's helpful to understand this for performance tuning. If there are such signals in the output, the program must be throwing these exceptions from a frequently called method which has been compiled. The interpreter uses SIGFPE for null pointer checks in the interpreter. If there are such signals in the output, the program is causing these exceptions from interpreted methods. The JVM is designed to execute the normal non-exception-throwing case as fast as possible, but the exception-throwing case is quite expensive, so to get good performance it is important to eliminate any extra exceptions caused by careless coding. You can use tusc to detect if this is happening, since if you have correct exception-handling routines in your program you might not notice it, but you would have lower overall performance than you could otherwise achieve.

read(24, "\0q \0\006\0\0\0", 8) .......................... = 8
send(42, "\0\0\01706e \0\0\098a5\0\098a5\0".., 23, 0) .... = 23
sigsetstatemask(0x17, NULL, 1135461680) .................. = 0
read(24, "\0\006020105\001\n\0\a\0810102c1".., 105) ...... = 105
  Received signal 11, SIGSEGV, in user mode, [0xbaf215a2], partial siginfo
    Siginfo: si_code: I_NONEXIST, faulting address: 0x8, si_errno: 0
    PC: 0xb92eb3c7, instruction: 0x0eb01096
sigsetstatemask(0x17, NULL, 1135460976) .................. = 0
  Received signal 8, SIGFPE, in user mode, [0xbaf215a2], partial siginfo
    Siginfo: si_code: I_COND, faulting address: 0x1132ab, si_errno: 0
    PC: 0x1132ab, instruction: 0x0a6024c0
send(24, "\00f\0\006\0\0\0\0\00314\00114", 15, 0) ........ = 15
  Received signal 11, SIGSEGV, in user mode, [0xbaf215a2], partial siginfo
    Siginfo: si_code: I_NONEXIST, faulting address: 0x8, si_errno: 0
    PC: 0xb8d73d4b, instruction: 0x0cd01096
sigsetstatemask(0x17, NULL, 1135461104) .................. = 0

In this output, we are not showing the lwp id or timestamp. Here we have thrown a couple exceptions in a row. The SIGSEGV will result in NullPointerExceptions from hotspot-compiled code, and the SIGFPE will result in a NullPointerException from interpreted Java code. To get the best performance, avoid throwing exceptions whenever possible. You can measure the count of such exceptions happening at runtime with tusc, then use HPjmeter to determine where they are happening. It requires thousands of machine instructions to throw the exception, while it usually requires little effort up front to minimize them. To determine the source of the NullPointerExceptions, make an -Xeprof trace and view the data with HPjmeter. HPjmeter has built-in features to examine exception handling.

Return values

Another great thing about tusc is that you can see the system call return values.

close(34) ................................................ = 0
send(20, "\00f\0\006\0\0\0\0\00314\00115", 15, 0) ........ = 15
sigsetstatemask(0x17, NULL, 1134403888) .................. = 0
read(6, 0x43852a68, 5) ................................... ERR#11 EAGAIN
sigsetstatemask(0x17, NULL, 1133867888) .................. = 0
poll(0x4a1af0, 6, -1) .................................... = 1

Here we can see that the read returned with EAGAIN. This kind of information may be useful for diagnosing various problems. Below we can see a new thread being created. First the mmap for the thread stack, then the _lwp_create happens. Lastly, the sigaltstack() installs the signal stack on the new thread.

1008628500.575606 {19792} sched_yield() .......................... = 0
1008628500.575784 {19792} sched_yield() .......................... = 0
1008628500.575952 {19792} sched_yield() .......................... = 0
1008628500.576072 {19616} mmap(NULL, 528384, PROT_READ|PROT_WRITE, \ 
    MAP_PRIVATE|MAP_ANONYMOUS, 0, NULL) = 0x6a8a5000
1008628500.576197 {19792} sched_yield() .......................... = 0
1008628500.576312 {19616} mprotect(0x6a925000, 4096, PROT_NONE) .. = 0
1008628500.576424 {19792} sched_yield() .......................... = 0
1008628500.576588 {19792} sched_yield() .......................... = 0
1008628500.576753 {19616} _lwp_create(0x77ff1c00, \ 
    LWP_DETACHED|LWP_INHERIT_SIGMASK|LWP_USER_TID, \ 
    0x471fd4, 0x77ff20d8) = 0 (19934)
1008628500.576948 {19934} _lwp_self() ............................ = 19934
1008628500.577179 {19792} sched_yield() .......................... = 0
1008628500.577274 {19616} kwakeup(PTH_MUTEX_OBJECT, 0xaae8, WAKEUP_ONE, \ 
    0x77ff1a8c) = 0
1008628500.577365 {19869} ksleep(PTH_MUTEX_OBJECT, 0xaae8, 0xaaf0, \ 
    NULL) = 0
1008628500.577462 {19896} kwakeup(PTH_CONDVAR_OBJECT, 0x45ee20, \ 
    WAKEUP_ALL, 0x6acad848) = 0
1008628500.577552 {19897} ksleep(PTH_CONDVAR_OBJECT, 0x45ee20, 0x45ee28, \ 
    0x6ac2c908) = 0
1008628500.577663 {19778} sched_yield() .......................... = 0
1008628500.577769 {19934} sigaltstack(0x6a8a50b8, NULL) .......... = 0
1008628500.577881 {19792} sched_yield() .......................... = 0
1008628500.578008 {19616} sched_yield() .......................... = 0

The new thread is 19934, and the first thing he does is call _lwp_self(). Remember that the lwp id is also shown in Java stack traces, and in GlancePlus in the Process Thread List window, so you can correlate the tusc data with other data.

Last modified: March 07, 2005



Manage My AllianceOne Membership

 
 » Sign in
 » Join AllianceOne
 » Contact us