This discussion is archived
3 Replies Latest reply: Feb 2, 2011 10:22 AM by 836351 RSS

JVM lockup- how do debug further

843829 Newbie
Currently Being Moderated
Hi folks,

We're seeing a jvm lockup- meaning, the jvm stops executing java code, doesn't respond to thread dump requests, truss of the jvm process (below) suggests some broken locking internal to the jvm- the question is, how do we debug this further, e.g., to figure out what java code was last executed, or what jvm subsystem owned the locks that jvm lwps are sleeping against?

The application is a custom multithreaded java server application running on jdk 1.4.2.08 with the DST patch, on sparc solaris 10. We're running one instance of the application apiece on each of 3 v440s.

The application services RMI and TCP socket clients, and talks to an Oracle 10g database. The subsystem which supports TCP socket clients is built on java.nio, which, because of bug reports against nio on 1.4.x, we suspect for causing this problem. We also have never seen the problem on an RMI-only workload, but because of how the application works we can't run a TCP-only workload, and we're otherwise not sure how to isolate the issue to the TCP/nio- or other- subsystem.

The lockups occur at random at a rate of about one per day, at all times of day and night, with nothing discernably unique in the request pattern or in the workload prior to the lockup. We don't have control over most of the source of the app, so adding logging isn't an option. Attempts to reproduce the problem outside of the production environment have so far been unsuccessful.

Java is:

user@host: /usr/local/java14_home/bin/java -version
java version "1.4.2_08"
Java(TM) 2 Runtime Environment, Standard Edition (build 1.4.2_08-b03)
Java HotSpot(TM) Client VM (build 1.4.2_08-b03, mixed mode)

Solaris is:

user@host: uname -a
SunOS host 5.10 Generic_118833-22 sun4u sparc SUNW,Sun-Fire-V440

Truss looks like:

user@host: truss -p `cat /xxx.pid`
/37: lwp_cond_wait(0x017BADB8, 0x017BADA0, 0x00000000, 0)
(sleeping...)
/47: lwp_mutex_timedlock(0x00039680, 0x00000000) (sleeping...)
/54: lwp_mutex_timedlock(0x00039680, 0x00000000) (sleeping...)
/15: lwp_cond_wait(0x00039BA0, 0x00039B88, 0x00000000, 0)
(sleeping...)
/40: lwp_mutex_timedlock(0x00039680, 0x00000000) (sleeping...)
/6: lwp_cond_wait(0x00038EB8, 0x00038EA0, 0xF94FFDD8, 0)
(sleeping...)
/16: lwp_cond_wait(0x00039C08, 0x00039BF0, 0x00000000, 0)
(sleeping...)
/31: lwp_mutex_timedlock(0x00039680, 0x00000000) (sleeping...)
/26: pollsys(0xACB7F7A8, 0, 0xACB7F810, 0x00000000) (sleeping...)
/13: lwp_cond_wait(0x00039098, 0x00039080, 0x00000000, 0)
(sleeping...)
/105: lwp_cond_wait(0x0162F820, 0x0162F808, 0x00000000, 0)
(sleeping...)
/5: lwp_cond_wait(0x000BE138, 0x000BE120, 0x00000000, 0)
(sleeping...)
/23: lwp_mutex_timedlock(0x00039680, 0x00000000) (sleeping...)
/4: lwp_cond_wait(0x000BE138, 0x000BE120, 0x00000000, 0)
(sleeping...)
/58: lwp_cond_wait(0x01A8F760, 0x01A8F748, 0x00000000, 0)
(sleeping...)
/30: lwp_mutex_timedlock(0x00039680, 0x00000000) (sleeping...)
/143398: lwp_cond_wait(0x0051C3F8, 0x0051C3E0, 0x00000000, 0)
(sleeping...)
/149245: lwp_cond_wait(0x017E8C48, 0x017E8C30, 0x00000000, 0)
(sleeping...)
/83: lwp_mutex_timedlock(0x00039680, 0x00000000) (sleeping...)
/11: accept(6, 0xB0B7FDB8, 0xB0B7FDB4, SOV_DEFAULT) (sleeping...)
/149244: lwp_cond_wait(0x00FE8E30, 0x00FE8E18, 0x00000000, 0)
(sleeping...)
/149231: lwp_cond_wait(0x00F95888, 0x00F95870, 0x00000000, 0)
(sleeping...)
/95: lwp_mutex_timedlock(0x00039680, 0x00000000) (sleeping...)
/149360: lwp_cond_wait(0x00039768, 0x00039750, 0x00000000, 0)
(sleeping...)
/124531: lwp_mutex_timedlock(0x00039680, 0x00000000)
(sleeping...)
/63: lwp_mutex_timedlock(0x00039680, 0x00000000) (sleeping...)
/149239: lwp_cond_wait(0x00EBD458, 0x00EBD440, 0x00000000, 0)
(sleeping...)
/77955: lwp_mutex_timedlock(0x00039680, 0x00000000) (sleeping...)
/111: lwp_cond_wait(0x0151D300, 0x0151D2E8, 0x00000000, 0)
(sleeping...)
/124: lwp_cond_wait(0x0088A898, 0x0088A880, 0x00000000, 0)
(sleeping...)
/126: lwp_cond_wait(0x01517DD8, 0x01517DC0, 0xA737F7A8, 0)
(sleeping...)
/84571: lwp_cond_wait(0x007343E0, 0x007343C8, 0x00000000, 0)
(sleeping...)
/84: lwp_mutex_timedlock(0x00039680, 0x00000000) (sleeping...)
/117: lwp_mutex_timedlock(0x00039680, 0x00000000) (sleeping...)
/60: lwp_cond_wait(0x01A8F988, 0x01A8F970, 0x00000000, 0)
(sleeping...)
/68: lwp_cond_wait(0x013567B0, 0x01356798, 0x00000000, 0)
(sleeping...)
/85780: lwp_mutex_timedlock(0x00039680, 0x00000000) (sleeping...)
/108: lwp_cond_wait(0x01B9AD48, 0x01B9AD30, 0x00000000, 0)
(sleeping...)
/149358: lwp_mutex_timedlock(0x00039680, 0x00000000)
(sleeping...)
/77957: lwp_mutex_timedlock(0x00039680, 0x00000000) (sleeping...)
/149347: lwp_mutex_timedlock(0x00039680, 0x00000000)
(sleeping...)
/143389: lwp_cond_wait(0x00EBD420, 0x00EBD408, 0x00000000, 0)
(sleeping...)
/67: lwp_cond_wait(0x0120D520, 0x0120D508, 0x00000000, 0)
(sleeping...)
/149346: pollsys(0xA8B7EF08, 1, 0xA8B7EE98, 0x00000000)
(sleeping...)
/62: lwp_cond_wait(0x0120E1F0, 0x0120E1D8, 0x00000000, 0)
(sleeping...)
/66: lwp_cond_wait(0x0120CCE0, 0x0120CCC8, 0x00000000, 0)
(sleeping...)
/115: lwp_cond_wait(0x01245830, 0x01245818, 0xA7D7F7A8, 0)
(sleeping...)
/14148: lwp_mutex_timedlock(0x00039680, 0x00000000) (sleeping...)
/123502: lwp_mutex_timedlock(0x00039680, 0x00000000)
(sleeping...)
/123: lwp_cond_wait(0x0088A728, 0x0088A710, 0xA767F7A8, 0)
(sleeping...)
/115951: lwp_cond_wait(0x0053F758, 0x0053F740, 0x00000000, 0)
(sleeping...)
/143342: lwp_cond_wait(0x013480E0, 0x013480C8, 0x00000000, 0)
(sleeping...)
/149343: lwp_mutex_timedlock(0x00039680, 0x00000000)
(sleeping...)
/73774: lwp_mutex_timedlock(0x00039680, 0x00000000) (sleeping...)
/149234: lwp_cond_wait(0x017D1848, 0x017D1830, 0x00000000, 0)
(sleeping...)
/143390: lwp_cond_wait(0x017E67F8, 0x017E67E0, 0x00000000, 0)
(sleeping...)
/149357: lwp_mutex_timedlock(0x00039680, 0x00000000)
(sleeping...)
/125: lwp_mutex_timedlock(0x00039680, 0x00000000) (sleeping...)
/112: lwp_cond_wait(0x012440D0, 0x012440B8, 0x00000000, 0)
(sleeping...)
/149198: lwp_mutex_timedlock(0x00039680, 0x00000000)
(sleeping...)
/149241: lwp_cond_wait(0x0120AE60, 0x0120AE48, 0x00000000, 0)
(sleeping...)
/140951: lwp_cond_wait(0x00A8A788, 0x00A8A770, 0x00000000, 0)
(sleeping...)
/149330: lwp_mutex_timedlock(0x00039680, 0x00000000)
(sleeping...)
/109: lwp_cond_wait(0x01B9AE10, 0x01B9ADF8, 0x00000000, 0)
(sleeping...)
/64: lwp_cond_wait(0x0120B098, 0x0120B080, 0x00000000, 0)
(sleeping...)
/120: lwp_cond_wait(0x01596790, 0x01596778, 0xA797F7A8, 0)
(sleeping...)
/149359: lwp_mutex_timedlock(0x00039680, 0x00000000)
(sleeping...)
/149342: lwp_mutex_timedlock(0x00039680, 0x00000000)
(sleeping...)
/110: lwp_cond_wait(0x010B27A0, 0x010B2788, 0x00000000, 0)
(sleeping...)
/96: lwp_mutex_timedlock(0x00039680, 0x00000000) (sleeping...)
/75: lwp_mutex_timedlock(0x00039680, 0x00000000) (sleeping...)
/69: lwp_mutex_timedlock(0x00039680, 0x00000000) (sleeping...)
/65: lwp_cond_wait(0x01355540, 0x01355528, 0x00000000, 0)
(sleeping...)
/113: lwp_cond_wait(0x01244A30, 0x01244A18, 0x00000000, 0)
(sleeping...)
/129: lwp_mutex_timedlock(0x00039680, 0x00000000) (sleeping...)
/127: lwp_mutex_timedlock(0x00039680, 0x00000000) (sleeping...)
/143395: lwp_cond_wait(0x01ED19E0, 0x01ED19C8, 0x00000000, 0)
(sleeping...)
/71288: lwp_mutex_timedlock(0x00039680, 0x00000000) (sleeping...)
/59: lwp_cond_wait(0x0198D908, 0x0198D8F0, 0x00000000, 0)
(sleeping...)

What do we do next?

Thanks-

Jonah
  • 1. Re: JVM lockup- how do debug further
    843829 Newbie
    Currently Being Moderated
    I have experienced this using a number of different java versions 1.4 1.5 & 1.6

    I have repeatedly logged this issue with sun but unfortunetly this is ignored without any further investigation or feedback.

    This is a real issue with Production Servers and sun is ignoring the issue.
  • 2. Re: JVM lockup- how do debug further
    843829 Newbie
    Currently Being Moderated
    We are currently facing something very much like this, hanging application / hanging server, with Truss output similar to above: see here:

    /u01/app/tomcat
    Using CATALINA_BASE: /u01/app/tomcat
    Using CATALINA_HOME: /u01/app/tomcat
    Using CATALINA_TMPDIR: /u01/app/tomcat/temp
    Using JRE_HOME: /u01/app/jdk
    Server version: Apache Tomcat/5.5.27
    Server built: Aug 28 2008 10:08:26
    Server number: 5.5.27.0
    OS Name: SunOS
    OS Version: 5.10
    Architecture: x86
    JVM Version: 1.5.0_14-b03
    JVM Vendor: Sun Microsystems Inc.
    +

    25743/6: lwp_cond_wait(0x08311BA8, 0x08311B90, 0xFAF9BC98, 0) Err#62 ETIME
    25743/6: condvar type: USYNC_THREAD
    25743/6: mutex type: USYNC_THREAD
    25743/6: timeout: 0.010998286 sec
    25743/19: pollsys(0x00000000, 0, 0x73119BE0, 0x00000000) = 0
    25743/19: timeout: 0.050000000 sec
    25743/65: pollsys(0x00000000, 0, 0x70091B98, 0x00000000) = 0
    25743/65: timeout: 0.010000000 sec
    25743/129: pollsys(0x00000000, 0, 0x6E291BA0, 0x00000000) = 0
    25743/129: timeout: 0.010000000 sec
    25743/6: lwp_cond_wait(0x08311BA8, 0x08311B90, 0xFAF9BC98, 0) Err#62 ETIME
    25743/6: condvar type: USYNC_THREAD
    25743/6: mutex type: USYNC_THREAD
    25743/6: timeout: 0.010998578 sec
    25743/65: pollsys(0x00000000, 0, 0x70091B98, 0x00000000) = 0
    25743/65: timeout: 0.010000000 sec
    25743/129: pollsys(0x00000000, 0, 0x6E291BA0, 0x00000000) = 0
    25743/129: timeout: 0.010000000 sec
    25743/6: lwp_cond_wait(0x08311BA8, 0x08311B90, 0xFAF9BC98, 0) Err#62 ETIME
    25743/6: condvar type: USYNC_THREAD
    25743/6: mutex type: USYNC_THREAD
    25743/6: timeout: 0.010998020 sec

    This truss was taken when the application was in the problem state.

    Anyone further in to this problem, any experience?
  • 3. Re: JVM lockup- how do debug further
    836351 Newbie
    Currently Being Moderated
    even I am facing the same issue. Did u get any clue what may be causing this issue?
    Please let me know. It will be helpful for me.
    Thanks in advance..
    Base time stamp: 1296148661.4107 [ Thu Jan 27 12:17:41 EST 2011 ]
    16276/1:     psargs: /idmapp/AppServer/jdk/bin/java -server -XX:NewRatio=2 -Xms3072m
    16276/35:     67303.2710     67303.2710     pollsys(0x00000000, 0, 0x2897FA90, 0x00000000)     = 0
    16276/35:          timeout: 0.050000000 sec
    16276/75:     67303.3172     67303.3172     lwp_cond_wait(0x00BBE738, 0x00BBE720, 0x20CFF448, 0) Err#62 ETIME
    16276/75:          condvar type: USYNC_THREAD
    16276/75:          mutex type: USYNC_THREAD
    16276/75:          timeout: 4.527997185 sec
    16276/75:     67303.3210     0.0038     ioctl(802, DP_POLL, 0x20CFEEBC)               = 1
    16276/75:     67303.3213     0.0003     write(796, 0x00DCC000, 223)               = 223
    16276/75:     \0DF\0\006\0\0\0\0\003 ^\00280 )\00101 m0101\r\0\004FFFFFFFF01\n
    16276/75:     047FFFFFFF010102\0\0\0\0\0\0\0\0\001 S E L E C T t i m e s t a
    16276/75:     m p , i d , v e r s i o n , c h a n g e T y p e F R O M
    16276/75:     o b j c h a n g e W H E R E t i m e s t a m p > : 1
    16276/75:     A N D t y p e = : 2 O R D E R B Y t i m e s t a m p01
    16276/75:     01\0\0\0\0\0\00101\0\0\0\0\0B403\0\001\v\0\0\0\00203 i01\00103\0
    16276/75:     \00110\00110\0\00203 i01\007\v x m\v07060516 38EDA @04 R u l e
    16276/75:     67303.3234     0.0021     ioctl(799, DP_POLL, 0x20CFEEF4)               = 1
    16276/75:     67303.3235     0.0001     read(796, "01\n\0\006\0\0\0", 8)          = 8
    16276/75:     67303.3251     0.0016     ioctl(799, DP_POLL, 0x20CFEEF4)               = 1
    16276/75:     67303.3252     0.0001     read(796, 0x00DCC000, 258)               = 258
    16276/75:     \0\010171C131A01 j ; | > {86BD @961B bC2 x o011C03 $0601 T0104 M
    16276/75:     B4\0\0010301\v\0\0\0\0\0\0\0\0\t01\t\t T I M E S T A M P\0\0\001
    16276/75:     80\0\001 2\0\0\0\00203 i0101 2\002010202 I D\0\0010102\013\00116
    16276/75:     \0\0\0\0\0\0\0\007010707 V E R S I O N\0\00102 `80\0\00101\0\0\0
    16276/75:     \00203 i010101\0\n01\n\n C H A N G E T Y P E\0\00103010707 x o01
    16276/75:     1C07 <190101021FE801\n01\n\b010604\r %9919\001\b\0\0\0\0\0\00402
    16276/75:     +F1\00205 {\0\001\b\003\001  \0\0\002 0 {0104\0030698 v0103\0\0
    16276/75:     \0\00101\0\0\0\019 O R A - 0 1 4 0 3 : n o d a t a f o u n
    16276/75:     d\n
    16276/75:     67303.3269     0.0017     ioctl(802, DP_POLL, 0x20CFF11C)               = 1
    16276/75:     67303.3271     0.0002     write(796, 0x00DCC000, 21)               = 21
    16276/75:     \015\0\006\0\0\0\0\011 i\001010101\b030E\0
    16276/35:     67303.3272     0.0562     pollsys(0x00000000, 0, 0x2897FA90, 0x00000000)     = 0
    16276/35:          timeout: 0.050000000 sec
    16276/75:     67303.3287     0.0016     ioctl(799, DP_POLL, 0x20CFF154)               = 1
    16276/75:     67303.3289     0.0002     read(796, "\00E\0\006\0\0\0", 8)          = 8
    16276/75:     67303.3304     0.0015     ioctl(799, DP_POLL, 0x20CFF154)               = 1
    16276/75:     67303.3306     0.0002     read(796, "\0\0\t02 +F3", 6)               = 6
    16276/75:     67303.3323     0.0017     ioctl(802, DP_POLL, 0x20CFEEBC)               = 1
    16276/75:     67303.3325     0.0002     write(796, 0x00DCC000, 235)               = 235
    16276/75:     \0EB\0\006\0\0\0\0\003 ^\00280 )\00101 m0101\r\0\004FFFFFFFF01\n
    16276/75:     047FFFFFFF010102\0\0\0\0\0\0\0\0\001 S E L E C T t i m e s t a
    16276/75:     m p , i d , v e r s i o n , c h a n g e T y p e F R O M
    16276/75:     o b j c h a n g e W H E R E t i m e s t a m p > : 1
    16276/75:     A N D t y p e = : 2 O R D E R B Y t i m e s t a m p01
    16276/75:     01\0\0\0\0\0\00101\0\0\0\0\0B403\0\001\v\0\0\0\00203 i01\00103\0
    16276/75:     \001 @\00110\0\00203 i01\007\v x l05171504 602 CD58010 P r o v i
    16276/75:     s i o n i n g T a s k
    16276/75:     67303.3341     0.0016     ioctl(799, DP_POLL, 0x20CFEEF4)               = 1
    16276/75:     67303.3342     0.0001     read(796, "01\n\0\006\0\0\0", 8)          = 8
    16276/75:     67303.3357     0.0015     ioctl(799, DP_POLL, 0x20CFEEF4)               = 1
    16276/75:     67303.3359     0.0002     read(796, 0x00DCC000, 258)               = 258
    16276/75:     \0\010171C131A01 j ; | > {86BD @961B bC2 x o011C03 $0601 T0104 M
    16276/75:     B4\0\0010301\v\0\0\0\0\0\0\0\0\t01\t\t T I M E S T A M P\0\0\001
    16276/75:     80\0\001 2\0\0\0\00203 i0101 2\002010202 I D\0\0010102\013\00116
    16276/75:     \0\0\0\0\0\0\0\007010707 V E R S I O N\0\00102 `80\0\00101\0\0\0
    16276/75:     \00203 i010101\0\n01\n\n C H A N G E T Y P E\0\00103010707 x o01
    16276/75:     1C07 <190101021FE801\n01\n\b010604\r %9919\001\t\0\0\0\0\0\00402
    16276/75:     +F4\00205 {\0\001\t\003\001  \0\0\002 0 {0104\0030698 v0103\0\0
    16276/75:     \0\00101\0\0\0\019 O R A - 0 1 4 0 3 : n o d a t a f o u n
    16276/75:     d\n
    16276/75:     67303.3376     0.0017     ioctl(802, DP_POLL, 0x20CFF11C)               = 1
    16276/75:     67303.3377     0.0001     write(796, 0x00DCC000, 21)               = 21
    16276/75:     \015\0\006\0\0\0\0\011 i\001010101\t030E\0
    16276/75:     67303.3392     0.0015     ioctl(799, DP_POLL, 0x20CFF154)               = 1
    16276/75:     67303.3394     0.0002     read(796, "\00E\0\006\0\0\0", 8)          = 8
    16276/75:     67303.3409     0.0015     ioctl(799, DP_POLL, 0x20CFF154)               = 1
    16276/75:     67303.3411     0.0002     read(796, "\0\0\t02 +F6", 6)               = 6
    16276/75:     67303.3428     0.0017     ioctl(802, DP_POLL, 0x20CFEEBC)               = 1
    16276/75:     67303.3430     0.0002     write(796, 0x00DCC000, 226)               = 226
    16276/75:     \0E2\0\006\0\0\0\0\003 ^\00280 )\00101 m0101\r\0\004FFFFFFFF01\n
    16276/75:     047FFFFFFF010102\0\0\0\0\0\0\0\0\001 S E L E C T t i m e s t a
    16276/75:     m p , i d , v e r s i o n , c h a n g e T y p e F R O M
    16276/75:     o b j c h a n g e W H E R E t i m e s t a m p > : 1
    16276/75:     A N D t y p e = : 2 O R D E R B Y t i m e s t a m p01
    16276/75:     01\0\0\0\0\0\00101\0\0\0\0\0B403\0\001\v\0\0\0\00203 i01\00103\0
    16276/75:     \001 ,\00110\0\00203 i01\00707 wA9\f1F140101\v U s a g e R e p o
    16276/75:     r t
    16276/75:     67303.3445     0.0015     ioctl(799, DP_POLL, 0x20CFEEF4)               = 1
    16276/75:     67303.3447     0.0002     read(796, "01\n\0\006\0\0\0", 8)          = 8
    16276/75:     67303.3462     0.0015     ioctl(799, DP_POLL, 0x20CFEEF4)               = 1
    16276/75:     67303.3463     0.0001     read(796, 0x00DCC000, 258)               = 258
    16276/75:     \0\010171C131A01 j ; | > {86BD @961B bC2 x o011C03 $0601 T0104 M
    16276/75:     B4\0\0010301\v\0\0\0\0\0\0\0\0\t01\t\t T I M E S T A M P\0\0\001
    16276/75:     80\0\001 2\0\0\0\00203 i0101 2\002010202 I D\0\0010102\013\00116
    16276/75:     \0\0\0\0\0\0\0\007010707 V E R S I O N\0\00102 `80\0\00101\0\0\0
    16276/75:     \00203 i010101\0\n01\n\n C H A N G E T Y P E\0\00103010707 x o01
    16276/75:     1C07 <190101021FE801\n01\n\b010604\r %9919\001\b\0\0\0\0\0\00402
    16276/75:     +F7\00205 {\0\001\b\003\001  \0\0\002 0 {0104\0030698 v0103\0\0
    16276/75:     \0\00101\0\0\0\019 O R A - 0 1 4 0 3 : n o d a t a f o u n
    16276/75:     d\n
    16276/75:     67303.3480     0.0017     ioctl(802, DP_POLL, 0x20CFF11C)               = 1
    16276/75:     67303.3482     0.0002     write(796, 0x00DCC000, 21)               = 21
    16276/75:     \015\0\006\0\0\0\0\011 i\001010101\b030E\0
    16276/75:     67303.3497     0.0015     ioctl(799, DP_POLL, 0x20CFF154)               = 1
    16276/75:     67303.3498     0.0001     read(796, "\00E\0\006\0\0\0", 8)          = 8
    16276/75:     67303.3514     0.0016     ioctl(799, DP_POLL, 0x20CFF154)               = 1
    16276/75:     67303.3515     0.0001     read(796, "\0\0\t02 +F9", 6)               = 6
    16276/75:     67303.3533     0.0018     ioctl(802, DP_POLL, 0x20CFEEBC)               = 1
    16276/75:     67303.3534     0.0001     write(796, 0x00DCC000, 231)               = 231
    16276/75:     \0E7\0\006\0\0\0\0\003 ^\00280 )\00101 m0101\r\0\004FFFFFFFF01\n
    16276/75:     047FFFFFFF010102\0\0\0\0\0\0\0\0\001 S E L E C T t i m e s t a
    16276/75:     m p , i d , v e r s i o n , c h a n g e T y p e F R O M
    16276/75:     o b j c h a n g e W H E R E t i m e s t a m p > : 1
    16276/75:     A N D t y p e = : 2 O R D E R B Y t i m e s t a m p01
    16276/75:     01\0\0\0\0\0\00101\0\0\0\0\0B403\0\001\v\0\0\0\00203 i01\00103\0
    16276/75:     \001 0\00110\0\00203 i01\007\v x l051715041A16 i N\0\f R e s o u
    16276/75:     r c e F o r m
    16276/75:     67303.3550     0.0016     ioctl(799, DP_POLL, 0x20CFEEF4)               = 1
    16276/75:     67303.3551     0.0001     read(796, "01\n\0\006\0\0\0", 8)          = 8
    16276/75:     67303.3567     0.0016     ioctl(799, DP_POLL, 0x20CFEEF4)               = 1
    16276/75:     67303.3568     0.0001     read(796, 0x00DCC000, 258)               = 258
    16276/75:     \0\010171C131A01 j ; | > {86BD @961B bC2 x o011C03 $0601 T0104 M
    16276/75:     B4\0\0010301\v\0\0\0\0\0\0\0\0\t01\t\t T I M E S T A M P\0\0\001
    16276/75:     80\0\001 2\0\0\0\00203 i0101 2\002010202 I D\0\0010102\013\00116
    16276/75:     \0\0\0\0\0\0\0\007010707 V E R S I O N\0\00102 `80\0\00101\0\0\0
    16276/75:     \00203 i010101\0\n01\n\n C H A N G E T Y P E\0\00103010707 x o01
    16276/75:     1C07 <190101021FE801\n01\n\b010604\r %9919\001\t\0\0\0\0\0\00402
    16276/75:     +FA\00205 {\0\001\t\003\001  \0\0\002 0 {0104\0030698 v0103\0\0
    16276/75:     \0\00101\0\0\0\019 O R A - 0 1 4 0 3 : n o d a t a f o u n
    16276/75:     d\n
    16276/75:     67303.3586     0.0018     ioctl(802, DP_POLL, 0x20CFF11C)               = 1
    16276/75:     67303.3588     0.0002     write(796, 0x00DCC000, 21)               = 21
    16276/75:     \015\0\006\0\0\0\0\011 i\001010101\t030E\0
    16276/75:     67303.3603     0.0015     ioctl(799, DP_POLL, 0x20CFF154)               = 1
    16276/75:     67303.3605     0.0002     read(796, "\00E\0\006\0\0\0", 8)          = 8
    16276/75:     67303.3620     0.0015     ioctl(799, DP_POLL, 0x20CFF154)               = 1
    16276/75:     67303.3621     0.0001     read(796, "\0\0\t02 +FC", 6)               = 6
    16276/35:     67303.3872     0.0600     pollsys(0x00000000, 0, 0x2897FA90, 0x00000000)     = 0
    16276/35:          timeout: 0.050000000 sec
    16276/75:     67303.3972     0.0351     lwp_cond_wait(0x00BBE738, 0x00BBE720, 0x20CFF448, 0) Err#62 ETIME
    16276/75:          condvar type: USYNC_THREAD
    16276/75:          mutex type: USYNC_THREAD
    16276/75:          timeout: 0.024997512 sec
    16276/75:     67303.4004     0.0032     ioctl(802, DP_POLL, 0x20CFEEBC)               = 1
    16276/75:     67303.4005     0.0001     write(796, 0x00DCC000, 225)               = 225
    16276/75:     \0E1\0\006\0\0\0\0\003 ^\00280 )\00101 m0101\r\0\004FFFFFFFF01\n
    16276/75:     047FFFFFFF010102\0\0\0\0\0\0\0\0\001 S E L E C T t i m e s t a
    16276/75:     m p , i d , v e r s i o n , c h a n g e T y p e F R O M
    16276/75:     o b j c h a n g e W H E R E t i m e s t a m p > : 1
    16276/75:     A N D t y p e = : 2 O R D E R B Y t i m e s t a m p01
    16276/75:     01\0\0\0\0\0\00101\0\0\0\0\0B403\0\001\v\0\0\0\00203 i01\00103\0
    16276/75:     \001 (\00110\0\00203 i01\00707 wA9\f1F140101\n A u d i t Q u e r
    16276/75:     y
    16276/75:     67303.4021     0.0016     ioctl(799, DP_POLL, 0x20CFEEF4)               = 1
    16276/75:     67303.4023     0.0002     read(796, "01\n\0\006\0\0\0", 8)          = 8
    16276/75:     67303.4038     0.0015     ioctl(799, DP_POLL, 0x20CFEEF4)               = 1
    16276/75:     67303.4039     0.0001     read(796, 0x00DCC000, 258)               = 258
    16276/75:     \0\010171C131A01 j ; | > {86BD @961B bC2 x o011C03 $0601 T0104 M
    16276/75:     B4\0\0010301\v\0\0\0\0\0\0\0\0\t01\t\t T I M E S T A M P\0\0\001
    16276/75:     80\0\001 2\0\0\0\00203 i0101 2\002010202 I D\0\0010102\013\00116
    16276/75:     \0\0\0\0\0\0\0\007010707 V E R S I O N\0\00102 `80\0\00101\0\0\0
    16276/75:     \00203 i010101\0\n01\n\n C H A N G E T Y P E\0\00103010707 x o01
    16276/75:     1C07 <190101021FE801\n01\n\b010604\r %9919\001\b\0\0\0\0\0\00402
    16276/75:     +FD\00205 {\0\001\b\003\001  \0\0\002 0 {0104\0030698 v0103\0\0
    16276/75:     \0\00101\0\0\0\019 O R A - 0 1 4 0 3 : n o d a t a f o u n
    16276/75:     d\n

    Edited by: 833348 on Feb 2, 2011 10:21 AM