3 Replies Latest reply: Feb 2, 2011 12:22 PM by 836351 RSS

    JVM lockup- how do debug further

    843829
      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
          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
            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
              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