Trace file d:\app\administrator\diag\rdbms\orcl\orcl\trace\cdmp_20250504082024\orcl_w000_3772_bucket.trc Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - 64bit Production With the Partitioning, OLAP, Data Mining and Real Application Testing options Windows NT Version V6.2 CPU : 32 - type 8664, 16 Physical Cores Process Affinity : 0x0x0000000000000000 Memory (Avail/Total): Ph:37569M/63366M, Ph+PgF:45050M/72582M Instance name: orcl Redo thread mounted by this instance: 1 Oracle process number: 25 Windows thread id: 3772, image: ORACLE.EXE (W000) *** 2025-05-04 08:20:24.959 *** SESSION ID:(201.34947) 2025-05-04 08:20:24.959 *** 2025-05-04 08:20:24.959 Process diagnostic dump for ORACLE.EXE (W000), OS id=3772, pid: 25, proc_ser: 94, sid: 201, sess_ser: 34947 ------------------------------------------------------------------------------- current sql: Current Wait Stack: 0: waiting for 'Space Manager: slave idle wait' Slave ID=0x0, =0x0, =0x0 wait_id=73 seq_num=74 snap_id=1 wait times: snap=1.436305 sec, exc=1.436305 sec, total=1.436305 sec wait times: max=5.000000 sec, heur=6 min 1 sec wait counts: calls=1 os=1 in_wait=1 iflags=0x5a8 Wait State: fixed_waits=0 flags=0x22 boundary=0x0000000000000000/-1 Session Wait History: elapsed time of 0.000043 sec since current wait 0: waited for 'Space Manager: slave idle wait' Slave ID=0x0, =0x0, =0x0 wait_id=72 seq_num=73 snap_id=1 wait times: snap=5.004643 sec, exc=5.004643 sec, total=5.004643 sec wait times: max=5.000000 sec wait counts: calls=1 os=1 occurred after 0.000020 sec of elapsed time 1: waited for 'Space Manager: slave idle wait' Slave ID=0x0, =0x0, =0x0 wait_id=71 seq_num=72 snap_id=1 wait times: snap=5.015243 sec, exc=5.015243 sec, total=5.015243 sec wait times: max=5.000000 sec wait counts: calls=1 os=1 occurred after 0.000022 sec of elapsed time 2: waited for 'Space Manager: slave idle wait' Slave ID=0x0, =0x0, =0x0 wait_id=70 seq_num=71 snap_id=1 wait times: snap=5.003204 sec, exc=5.003204 sec, total=5.003204 sec wait times: max=5.000000 sec wait counts: calls=1 os=1 occurred after 0.000027 sec of elapsed time 3: waited for 'Space Manager: slave idle wait' Slave ID=0x0, =0x0, =0x0 wait_id=69 seq_num=70 snap_id=1 wait times: snap=5.010104 sec, exc=5.010104 sec, total=5.010104 sec wait times: max=5.000000 sec wait counts: calls=1 os=1 occurred after 0.000021 sec of elapsed time 4: waited for 'Space Manager: slave idle wait' Slave ID=0x0, =0x0, =0x0 wait_id=68 seq_num=69 snap_id=1 wait times: snap=5.012498 sec, exc=5.012498 sec, total=5.012498 sec wait times: max=5.000000 sec wait counts: calls=1 os=1 occurred after 0.000027 sec of elapsed time 5: waited for 'Space Manager: slave idle wait' Slave ID=0x0, =0x0, =0x0 wait_id=67 seq_num=68 snap_id=1 wait times: snap=5.014730 sec, exc=5.014730 sec, total=5.014730 sec wait times: max=5.000000 sec wait counts: calls=1 os=1 occurred after 0.000020 sec of elapsed time 6: waited for 'Space Manager: slave idle wait' Slave ID=0x0, =0x0, =0x0 wait_id=66 seq_num=67 snap_id=1 wait times: snap=5.004635 sec, exc=5.004635 sec, total=5.004635 sec wait times: max=5.000000 sec wait counts: calls=1 os=1 occurred after 0.000022 sec of elapsed time 7: waited for 'Space Manager: slave idle wait' Slave ID=0x0, =0x0, =0x0 wait_id=65 seq_num=66 snap_id=1 wait times: snap=5.014741 sec, exc=5.014741 sec, total=5.014741 sec wait times: max=5.000000 sec wait counts: calls=1 os=1 occurred after 0.000024 sec of elapsed time 8: waited for 'Space Manager: slave idle wait' Slave ID=0x0, =0x0, =0x0 wait_id=64 seq_num=65 snap_id=1 wait times: snap=5.007228 sec, exc=5.007228 sec, total=5.007228 sec wait times: max=5.000000 sec wait counts: calls=1 os=1 occurred after 0.000022 sec of elapsed time 9: waited for 'Space Manager: slave idle wait' Slave ID=0x0, =0x0, =0x0 wait_id=63 seq_num=64 snap_id=1 wait times: snap=5.001396 sec, exc=5.001396 sec, total=5.001396 sec wait times: max=5.000000 sec wait counts: calls=1 os=1 occurred after 0.000020 sec of elapsed time Sampled Session History of session 201 serial 34947 --------------------------------------------------- The sampled session history is constructed by sampling the target session every 1 second. The sampling process captures at each sample if the session is in a non-idle wait, an idle wait, or not in a wait. If the session is in a non-idle wait then one interval is shown for all the samples the session was in the same non-idle wait. If the session is in an idle wait or not in a wait for consecutive samples then one interval is shown for all the consecutive samples. Though we display these consecutive samples in a single interval the session may NOT be continuously idle or not in a wait (the sampling process does not know). The history is displayed in reverse chronological order. sample interval: 1 sec, max history 120 sec --------------------------------------------------- [121 samples, 08:18:24 - 08:20:24] idle wait at each sample ------------------------------------------------------------------------------- Process diagnostic dump actual duration=0.000000 sec (max dump time=30.000000 sec) *** 2025-05-04 08:20:24.959 ------------------------------------------------------------------------------- Trace Bucket Dump Begin: default bucket for process 25 (osid: 3772, W000) TIME(*=approx):SEQ:COMPONENT:FILE@LINE:FUNCTION:SECT/DUMP: [EVENT#:PID:SID] DATA ------------------------------------------------------------------------------- 2025-05-04 06:32:18.947085 :9275190C:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:25:201] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-04 06:32:18.947252 :92751915:db_trace:ksl2.c@12699:ksliwat(): [10005:25:201] KSL POST RCVD poster=14 loc='ksl2.h LINE:2165 ID:kslpsr' id1=134 id2=0 name=EV type=0 fac#=0 facpost=1 2025-05-04 06:32:18.948048 :92751916:db_trace:kst.c@698:kstpsodel(): [10280:25:0] kst: process state object about to be deleted 2025-05-04 06:32:59.374508 :9275261D:db_trace:kst.c@673:kstipg(): [10280:25:0] kst: process state object created on 05-04 06:32:59.366 2025-05-04 06:32:59.374510 :9275261E:db_trace:kst.c@679:kstipg(): [10280:25:0] kst: process info: ospid=11596 pso_num=25 pso_serial#=77 2025-05-04 06:32:59.374644 :9275261F:db_trace:kso.c@4070:ksonfy(): [10420:25:0] kso: new process: pid=11596 (legacy spawn) 2025-05-04 06:32:59.381249 :92752620:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:25:201] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-04 06:32:59.381436 :92752625:db_trace:ksl2.c@12699:ksliwat(): [10005:25:201] KSL POST RCVD poster=14 loc='ksl2.h LINE:2165 ID:kslpsr' id1=134 id2=0 name=EV type=0 fac#=0 facpost=1 2025-05-04 06:32:59.382411 :9275262A:db_trace:kst.c@698:kstpsodel(): [10280:25:0] kst: process state object about to be deleted 2025-05-04 06:33:09.146653 :92752949:db_trace:kst.c@673:kstipg(): [10280:25:0] kst: process state object created on 05-04 06:33:09.138 2025-05-04 06:33:09.146656 :9275294A:db_trace:kst.c@679:kstipg(): [10280:25:0] kst: process info: ospid=10508 pso_num=25 pso_serial#=78 2025-05-04 06:33:09.146787 :9275294B:db_trace:kso.c@4070:ksonfy(): [10420:25:0] kso: new process: pid=10508 (legacy spawn) 2025-05-04 06:33:09.153239 :9275294C:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:25:201] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-04 06:33:09.153422 :92752951:db_trace:ksl2.c@12699:ksliwat(): [10005:25:201] KSL POST RCVD poster=14 loc='ksl2.h LINE:2165 ID:kslpsr' id1=134 id2=0 name=EV type=0 fac#=0 facpost=1 2025-05-04 06:33:09.154194 :92752956:db_trace:kst.c@698:kstpsodel(): [10280:25:0] kst: process state object about to be deleted 2025-05-04 06:34:04.827783 :92753B6B:db_trace:kst.c@673:kstipg(): [10280:25:0] kst: process state object created on 05-04 06:34:04.826 2025-05-04 06:34:04.827785 :92753B6C:db_trace:kst.c@679:kstipg(): [10280:25:0] kst: process info: ospid=9496 pso_num=25 pso_serial#=79 2025-05-04 06:34:04.827922 :92753B6D:db_trace:kso.c@4070:ksonfy(): [10420:25:0] kso: new process: pid=9496 (legacy spawn) 2025-05-04 06:34:04.834307 :92753B6E:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:25:201] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-04 06:34:04.834491 :92753B77:db_trace:ksl2.c@12699:ksliwat(): [10005:25:201] KSL POST RCVD poster=14 loc='ksl2.h LINE:2165 ID:kslpsr' id1=134 id2=0 name=EV type=0 fac#=0 facpost=1 2025-05-04 06:34:04.835279 :92753B78:db_trace:kst.c@698:kstpsodel(): [10280:25:0] kst: process state object about to be deleted 2025-05-04 06:34:04.843867 :92753B7B:db_trace:kst.c@673:kstipg(): [10280:25:0] kst: process state object created on 05-04 06:34:04.841 2025-05-04 06:34:04.843869 :92753B7C:db_trace:kst.c@679:kstipg(): [10280:25:0] kst: process info: ospid=11600 pso_num=25 pso_serial#=80 2025-05-04 06:34:04.844012 :92753B7D:db_trace:kso.c@4070:ksonfy(): [10420:25:0] kso: new process: pid=11600 (legacy spawn) 2025-05-04 06:34:04.850496 :92753B7E:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:25:201] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-04 06:34:04.850662 :92753B87:db_trace:ksl2.c@12699:ksliwat(): [10005:25:201] KSL POST RCVD poster=14 loc='ksl2.h LINE:2165 ID:kslpsr' id1=134 id2=0 name=EV type=0 fac#=0 facpost=1 2025-05-04 06:34:04.851471 :92753B88:db_trace:kst.c@698:kstpsodel(): [10280:25:0] kst: process state object about to be deleted 2025-05-04 06:34:05.231554 :92753B96:db_trace:kst.c@673:kstipg(): [10280:25:0] kst: process state object created on 05-04 06:34:05.216 2025-05-04 06:34:05.231556 :92753B97:db_trace:kst.c@679:kstipg(): [10280:25:0] kst: process info: ospid=12116 pso_num=25 pso_serial#=81 2025-05-04 06:34:05.231689 :92753B98:db_trace:kso.c@4070:ksonfy(): [10420:25:0] kso: new process: pid=12116 (legacy spawn) 2025-05-04 06:34:05.238155 :92753B99:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:25:201] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-04 06:34:05.238317 :92753BA2:db_trace:ksl2.c@12699:ksliwat(): [10005:25:201] KSL POST RCVD poster=14 loc='ksl2.h LINE:2165 ID:kslpsr' id1=134 id2=0 name=EV type=0 fac#=0 facpost=1 2025-05-04 06:34:05.239123 :92753BA3:db_trace:kst.c@698:kstpsodel(): [10280:25:0] kst: process state object about to be deleted 2025-05-04 06:34:05.247940 :92753BA6:db_trace:kst.c@673:kstipg(): [10280:25:0] kst: process state object created on 05-04 06:34:05.248 2025-05-04 06:34:05.247943 :92753BA7:db_trace:kst.c@679:kstipg(): [10280:25:0] kst: process info: ospid=12140 pso_num=25 pso_serial#=82 2025-05-04 06:34:05.248081 :92753BA8:db_trace:kso.c@4070:ksonfy(): [10420:25:0] kso: new process: pid=12140 (legacy spawn) 2025-05-04 06:34:05.254593 :92753BA9:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:25:201] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-04 06:34:05.254767 :92753BB2:db_trace:ksl2.c@12699:ksliwat(): [10005:25:201] KSL POST RCVD poster=14 loc='ksl2.h LINE:2165 ID:kslpsr' id1=134 id2=0 name=EV type=0 fac#=0 facpost=1 2025-05-04 06:34:05.255541 :92753BB3:db_trace:kst.c@698:kstpsodel(): [10280:25:0] kst: process state object about to be deleted 2025-05-04 06:34:08.427637 :92753CA6:db_trace:kst.c@673:kstipg(): [10280:25:0] kst: process state object created on 05-04 06:34:08.414 2025-05-04 06:34:08.427639 :92753CA7:db_trace:kst.c@679:kstipg(): [10280:25:0] kst: process info: ospid=7548 pso_num=25 pso_serial#=83 2025-05-04 06:34:08.427777 :92753CA8:db_trace:kso.c@4070:ksonfy(): [10420:25:0] kso: new process: pid=7548 (legacy spawn) 2025-05-04 06:34:08.434409 :92753CA9:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:25:201] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-04 06:34:08.434591 :92753CAE:db_trace:ksl2.c@12699:ksliwat(): [10005:25:201] KSL POST RCVD poster=14 loc='ksl2.h LINE:2165 ID:kslpsr' id1=134 id2=0 name=EV type=0 fac#=0 facpost=1 2025-05-04 06:34:08.435430 :92753CB3:db_trace:kst.c@698:kstpsodel(): [10280:25:0] kst: process state object about to be deleted 2025-05-04 06:34:08.454870 :92753CB6:db_trace:kst.c@673:kstipg(): [10280:25:0] kst: process state object created on 05-04 06:34:08.445 2025-05-04 06:34:08.454872 :92753CB7:db_trace:kst.c@679:kstipg(): [10280:25:0] kst: process info: ospid=6556 pso_num=25 pso_serial#=84 2025-05-04 06:34:08.455039 :92753CB8:db_trace:kso.c@4070:ksonfy(): [10420:25:0] kso: new process: pid=6556 (legacy spawn) 2025-05-04 06:34:08.461659 :92753CB9:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:25:201] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-04 06:34:08.461816 :92753CC2:db_trace:ksl2.c@12699:ksliwat(): [10005:25:201] KSL POST RCVD poster=14 loc='ksl2.h LINE:2165 ID:kslpsr' id1=134 id2=0 name=EV type=0 fac#=0 facpost=1 2025-05-04 06:34:08.462636 :92753CC3:db_trace:kst.c@698:kstpsodel(): [10280:25:0] kst: process state object about to be deleted 2025-05-04 06:34:12.002344 :92753E0A:db_trace:kst.c@673:kstipg(): [10280:25:0] kst: process state object created on 05-04 06:34:11.997 2025-05-04 06:34:12.002347 :92753E0B:db_trace:kst.c@679:kstipg(): [10280:25:0] kst: process info: ospid=12156 pso_num=25 pso_serial#=85 2025-05-04 06:34:12.002481 :92753E0C:db_trace:kso.c@4093:ksonfy(): [10420:25:0] kso: new process: pid=12156 osp_idx=23 osp_ver=74544 osp_pg=0 (spawn #146555) 2025-05-04 06:34:12.002481 :92753E0D:db_trace:kso.c@4099:ksonfy(): [10420:25:0] kso: new process: first_req_pid=1236 spawner_pid=3660 sga_crt_ts=x8A8A 2025-05-04 06:34:12.002482 :92753E0E:db_trace:kso.c@4103:ksonfy(): [10420:25:0] kso: new process: pso_index=25 reservation=223 time=3611229171 2025-05-04 06:34:12.002482 :92753E0F:db_trace:kso.c@4109:ksonfy(): [10420:25:0] kso: spawn diagnostics: queue time=0 secs 2025-05-04 06:34:12.002482 :92753E10:db_trace:kso.c@4111:ksonfy(): [10420:25:0] kso: spawn diagnostics: fork time=0 secs 2025-05-04 06:34:12.002483 :92753E11:db_trace:kso.c@4113:ksonfy(): [10420:25:0] kso: spawn diagnostics: exec time=0 secs 2025-05-04 06:34:12.002483 :92753E12:db_trace:kso.c@4115:ksonfy(): [10420:25:0] kso: spawn diagnostics: pre dbkc time=0 secs 2025-05-04 06:34:12.002484 :92753E13:db_trace:kso.c@4117:ksonfy(): [10420:25:0] kso: spawn diagnostics: post dbkc time=0 secs 2025-05-04 06:34:12.003048 :92753E14:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:25:201] KSL POST SENT postee=23 loc='kso2.h LINE:416 ID:ksoreq_reply' id1=0 id2=0 name= type=0 2025-05-04 06:34:12.003100 :92753E1B:db_trace:ksl2.c@12699:ksliwat(): [10005:25:201] KSL POST RCVD poster=23 loc='ksv2.h LINE:1639 ID:ksvpst: run' id1=0 id2=0 name= type=0 fac#=0 facpost=1 2025-05-04 06:44:12.949141 :927602E3:db_trace:kst.c@698:kstpsodel(): [10280:25:0] kst: process state object about to be deleted 2025-05-04 06:44:13.330553 :9276033D:db_trace:kst.c@673:kstipg(): [10280:25:0] kst: process state object created on 05-04 06:44:13.326 2025-05-04 06:44:13.330557 :9276033E:db_trace:kst.c@679:kstipg(): [10280:25:0] kst: process info: ospid=9832 pso_num=25 pso_serial#=86 2025-05-04 06:44:13.330699 :9276033F:db_trace:kso.c@4093:ksonfy(): [10420:25:0] kso: new process: pid=9832 osp_idx=23 osp_ver=74545 osp_pg=0 (spawn #146577) 2025-05-04 06:44:13.330700 :92760340:db_trace:kso.c@4099:ksonfy(): [10420:25:0] kso: new process: first_req_pid=1236 spawner_pid=3660 sga_crt_ts=x8A8A 2025-05-04 06:44:13.330701 :92760341:db_trace:kso.c@4103:ksonfy(): [10420:25:0] kso: new process: pso_index=25 reservation=224 time=3611830500 2025-05-04 06:44:13.330701 :92760342:db_trace:kso.c@4109:ksonfy(): [10420:25:0] kso: spawn diagnostics: queue time=0 secs 2025-05-04 06:44:13.330701 :92760343:db_trace:kso.c@4111:ksonfy(): [10420:25:0] kso: spawn diagnostics: fork time=0 secs 2025-05-04 06:44:13.330702 :92760344:db_trace:kso.c@4113:ksonfy(): [10420:25:0] kso: spawn diagnostics: exec time=0 secs 2025-05-04 06:44:13.330702 :92760345:db_trace:kso.c@4115:ksonfy(): [10420:25:0] kso: spawn diagnostics: pre dbkc time=0 secs 2025-05-04 06:44:13.330702 :92760346:db_trace:kso.c@4117:ksonfy(): [10420:25:0] kso: spawn diagnostics: post dbkc time=0 secs 2025-05-04 06:44:13.331180 :92760347:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:25:201] KSL POST SENT postee=23 loc='kso2.h LINE:416 ID:ksoreq_reply' id1=0 id2=0 name= type=0 2025-05-04 06:44:13.331226 :9276034E:db_trace:ksl2.c@12699:ksliwat(): [10005:25:201] KSL POST RCVD poster=23 loc='ksv2.h LINE:1639 ID:ksvpst: run' id1=0 id2=0 name= type=0 fac#=0 facpost=1 2025-05-04 06:53:42.808372 :9276BDFE:db_trace:ksl2.c@12699:ksliwat(): [10005:25:201] KSL POST RCVD poster=16 loc='ksl2.h LINE:2165 ID:kslpsr' id1=255 id2=0 name=EV type=0 fac#=0 facpost=1 2025-05-04 06:54:14.742221 :9276C888:db_trace:ksl2.c@12699:ksliwat(): [10005:25:201] KSL POST RCVD poster=23 loc='ksl2.h LINE:2165 ID:kslpsr' id1=255 id2=0 name=EV type=0 fac#=0 facpost=1 2025-05-04 06:54:14.742268 :9276C889:db_trace:ksl2.c@2477:kslwtbctx(): [10005:25:201] KSL WAIT BEG [latch free] 136537728/0x8236680 259/0x103 0/0x0 wait_id=123 seq_num=124 snap_id=1 2025-05-04 06:54:14.742306 :9276C88D:db_trace:ksl2.c@2611:kslwtectx(): [10005:25:201] KSL WAIT END [latch free] 136537728/0x8236680 259/0x103 0/0x0 wait_id=123 seq_num=124 snap_id=1 2025-05-04 06:54:14.742308 :9276C88F:db_trace:ksl2.c@2619:kslwtectx(): [10005:25:201] KSL WAIT END wait times (usecs) - snap=33, exc=33, tot=33 2025-05-04 07:04:15.634559 :92779048:db_trace:kst.c@698:kstpsodel(): [10280:25:0] kst: process state object about to be deleted 2025-05-04 07:04:16.196080 :927790A9:db_trace:kst.c@673:kstipg(): [10280:25:0] kst: process state object created on 05-04 07:04:16.191 2025-05-04 07:04:16.196082 :927790AA:db_trace:kst.c@679:kstipg(): [10280:25:0] kst: process info: ospid=11896 pso_num=25 pso_serial#=87 2025-05-04 07:04:16.196222 :927790AB:db_trace:kso.c@4093:ksonfy(): [10420:25:0] kso: new process: pid=11896 osp_idx=23 osp_ver=74546 osp_pg=0 (spawn #146627) 2025-05-04 07:04:16.196223 :927790AC:db_trace:kso.c@4099:ksonfy(): [10420:25:0] kso: new process: first_req_pid=1236 spawner_pid=3660 sga_crt_ts=x8A8A 2025-05-04 07:04:16.196223 :927790AD:db_trace:kso.c@4103:ksonfy(): [10420:25:0] kso: new process: pso_index=25 reservation=225 time=3613033359 2025-05-04 07:04:16.196224 :927790AE:db_trace:kso.c@4109:ksonfy(): [10420:25:0] kso: spawn diagnostics: queue time=0 secs 2025-05-04 07:04:16.196224 :927790AF:db_trace:kso.c@4111:ksonfy(): [10420:25:0] kso: spawn diagnostics: fork time=0 secs 2025-05-04 07:04:16.196225 :927790B0:db_trace:kso.c@4113:ksonfy(): [10420:25:0] kso: spawn diagnostics: exec time=0 secs 2025-05-04 07:04:16.196225 :927790B1:db_trace:kso.c@4115:ksonfy(): [10420:25:0] kso: spawn diagnostics: pre dbkc time=0 secs 2025-05-04 07:04:16.196225 :927790B2:db_trace:kso.c@4117:ksonfy(): [10420:25:0] kso: spawn diagnostics: post dbkc time=0 secs 2025-05-04 07:04:16.196727 :927790B3:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:25:201] KSL POST SENT postee=23 loc='kso2.h LINE:416 ID:ksoreq_reply' id1=0 id2=0 name= type=0 2025-05-04 07:04:16.196772 :927790B9:db_trace:ksl2.c@12699:ksliwat(): [10005:25:201] KSL POST RCVD poster=23 loc='ksv2.h LINE:1639 ID:ksvpst: run' id1=0 id2=0 name= type=0 fac#=0 facpost=1 2025-05-04 07:14:17.043332 :92785C6F:db_trace:kst.c@698:kstpsodel(): [10280:25:0] kst: process state object about to be deleted 2025-05-04 07:14:17.735395 :92785CD4:db_trace:kst.c@673:kstipg(): [10280:25:0] kst: process state object created on 05-04 07:14:17.730 2025-05-04 07:14:17.735397 :92785CD5:db_trace:kst.c@679:kstipg(): [10280:25:0] kst: process info: ospid=10684 pso_num=25 pso_serial#=88 2025-05-04 07:14:17.735535 :92785CD6:db_trace:kso.c@4093:ksonfy(): [10420:25:0] kso: new process: pid=10684 osp_idx=23 osp_ver=74547 osp_pg=0 (spawn #146649) 2025-05-04 07:14:17.735535 :92785CD7:db_trace:kso.c@4099:ksonfy(): [10420:25:0] kso: new process: first_req_pid=1236 spawner_pid=3660 sga_crt_ts=x8A8A 2025-05-04 07:14:17.735536 :92785CD8:db_trace:kso.c@4103:ksonfy(): [10420:25:0] kso: new process: pso_index=25 reservation=226 time=3613634906 2025-05-04 07:14:17.735536 :92785CD9:db_trace:kso.c@4109:ksonfy(): [10420:25:0] kso: spawn diagnostics: queue time=0 secs 2025-05-04 07:14:17.735537 :92785CDA:db_trace:kso.c@4111:ksonfy(): [10420:25:0] kso: spawn diagnostics: fork time=0 secs 2025-05-04 07:14:17.735537 :92785CDB:db_trace:kso.c@4113:ksonfy(): [10420:25:0] kso: spawn diagnostics: exec time=0 secs 2025-05-04 07:14:17.735537 :92785CDC:db_trace:kso.c@4115:ksonfy(): [10420:25:0] kso: spawn diagnostics: pre dbkc time=0 secs 2025-05-04 07:14:17.735538 :92785CDD:db_trace:kso.c@4117:ksonfy(): [10420:25:0] kso: spawn diagnostics: post dbkc time=0 secs 2025-05-04 07:14:17.736040 :92785CDE:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:25:201] KSL POST SENT postee=23 loc='kso2.h LINE:416 ID:ksoreq_reply' id1=0 id2=0 name= type=0 2025-05-04 07:14:17.736087 :92785CE4:db_trace:ksl2.c@12699:ksliwat(): [10005:25:201] KSL POST RCVD poster=23 loc='ksv2.h LINE:1639 ID:ksvpst: run' id1=0 id2=0 name= type=0 fac#=0 facpost=1 2025-05-04 07:24:18.601248 :9279250A:db_trace:kst.c@698:kstpsodel(): [10280:25:0] kst: process state object about to be deleted 2025-05-04 07:24:19.019849 :92792530:db_trace:kst.c@673:kstipg(): [10280:25:0] kst: process state object created on 05-04 07:24:19.007 2025-05-04 07:24:19.019851 :92792531:db_trace:kst.c@679:kstipg(): [10280:25:0] kst: process info: ospid=12012 pso_num=25 pso_serial#=89 2025-05-04 07:24:19.019989 :92792532:db_trace:kso.c@4070:ksonfy(): [10420:25:0] kso: new process: pid=12012 (legacy spawn) 2025-05-04 07:24:19.026350 :92792533:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:25:201] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-04 07:24:19.026519 :92792538:db_trace:ksl2.c@12699:ksliwat(): [10005:25:201] KSL POST RCVD poster=14 loc='ksl2.h LINE:2165 ID:kslpsr' id1=134 id2=0 name=EV type=0 fac#=0 facpost=1 2025-05-04 07:24:19.027292 :9279253D:db_trace:kst.c@698:kstpsodel(): [10280:25:0] kst: process state object about to be deleted 2025-05-04 07:24:19.116068 :92792577:db_trace:kst.c@673:kstipg(): [10280:25:0] kst: process state object created on 05-04 07:24:19.111 2025-05-04 07:24:19.116070 :92792578:db_trace:kst.c@679:kstipg(): [10280:25:0] kst: process info: ospid=10572 pso_num=25 pso_serial#=90 2025-05-04 07:24:19.116202 :92792579:db_trace:kso.c@4093:ksonfy(): [10420:25:0] kso: new process: pid=10572 osp_idx=23 osp_ver=74549 osp_pg=0 (spawn #146672) 2025-05-04 07:24:19.116203 :9279257A:db_trace:kso.c@4099:ksonfy(): [10420:25:0] kso: new process: first_req_pid=1236 spawner_pid=3660 sga_crt_ts=x8A8A 2025-05-04 07:24:19.116203 :9279257B:db_trace:kso.c@4103:ksonfy(): [10420:25:0] kso: new process: pso_index=25 reservation=227 time=3614236281 2025-05-04 07:24:19.116203 :9279257C:db_trace:kso.c@4109:ksonfy(): [10420:25:0] kso: spawn diagnostics: queue time=0 secs 2025-05-04 07:24:19.116204 :9279257D:db_trace:kso.c@4111:ksonfy(): [10420:25:0] kso: spawn diagnostics: fork time=0 secs 2025-05-04 07:24:19.116204 :9279257E:db_trace:kso.c@4113:ksonfy(): [10420:25:0] kso: spawn diagnostics: exec time=0 secs 2025-05-04 07:24:19.116205 :9279257F:db_trace:kso.c@4115:ksonfy(): [10420:25:0] kso: spawn diagnostics: pre dbkc time=0 secs 2025-05-04 07:24:19.116205 :92792580:db_trace:kso.c@4117:ksonfy(): [10420:25:0] kso: spawn diagnostics: post dbkc time=0 secs 2025-05-04 07:24:19.116749 :92792581:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:25:201] KSL POST SENT postee=23 loc='kso2.h LINE:416 ID:ksoreq_reply' id1=0 id2=0 name= type=0 2025-05-04 07:24:19.116795 :92792588:db_trace:ksl2.c@12699:ksliwat(): [10005:25:201] KSL POST RCVD poster=23 loc='ksv2.h LINE:1639 ID:ksvpst: run' id1=0 id2=0 name= type=0 fac#=0 facpost=1 2025-05-04 07:34:19.942209 :9279EB0D:db_trace:kst.c@698:kstpsodel(): [10280:25:0] kst: process state object about to be deleted 2025-05-04 07:34:20.603037 :9279EB78:db_trace:kst.c@673:kstipg(): [10280:25:0] kst: process state object created on 05-04 07:34:20.598 2025-05-04 07:34:20.603039 :9279EB79:db_trace:kst.c@679:kstipg(): [10280:25:0] kst: process info: ospid=11552 pso_num=25 pso_serial#=91 2025-05-04 07:34:20.603181 :9279EB7A:db_trace:kso.c@4093:ksonfy(): [10420:25:0] kso: new process: pid=11552 osp_idx=23 osp_ver=74550 osp_pg=0 (spawn #146695) 2025-05-04 07:34:20.603182 :9279EB7B:db_trace:kso.c@4099:ksonfy(): [10420:25:0] kso: new process: first_req_pid=1236 spawner_pid=3660 sga_crt_ts=x8A8A 2025-05-04 07:34:20.603182 :9279EB7C:db_trace:kso.c@4103:ksonfy(): [10420:25:0] kso: new process: pso_index=25 reservation=228 time=3614837765 2025-05-04 07:34:20.603183 :9279EB7D:db_trace:kso.c@4109:ksonfy(): [10420:25:0] kso: spawn diagnostics: queue time=0 secs 2025-05-04 07:34:20.603183 :9279EB7E:db_trace:kso.c@4111:ksonfy(): [10420:25:0] kso: spawn diagnostics: fork time=0 secs 2025-05-04 07:34:20.603184 :9279EB7F:db_trace:kso.c@4113:ksonfy(): [10420:25:0] kso: spawn diagnostics: exec time=0 secs 2025-05-04 07:34:20.603184 :9279EB80:db_trace:kso.c@4115:ksonfy(): [10420:25:0] kso: spawn diagnostics: pre dbkc time=0 secs 2025-05-04 07:34:20.603184 :9279EB81:db_trace:kso.c@4117:ksonfy(): [10420:25:0] kso: spawn diagnostics: post dbkc time=0 secs 2025-05-04 07:34:20.603694 :9279EB82:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:25:201] KSL POST SENT postee=23 loc='kso2.h LINE:416 ID:ksoreq_reply' id1=0 id2=0 name= type=0 2025-05-04 07:34:20.603748 :9279EB8B:db_trace:ksl2.c@12699:ksliwat(): [10005:25:201] KSL POST RCVD poster=23 loc='ksv2.h LINE:1639 ID:ksvpst: run' id1=0 id2=0 name= type=0 fac#=0 facpost=1 2025-05-04 07:44:21.470395 :927AB1D4:db_trace:kst.c@698:kstpsodel(): [10280:25:0] kst: process state object about to be deleted 2025-05-04 07:44:21.959465 :927AB23B:db_trace:kst.c@673:kstipg(): [10280:25:0] kst: process state object created on 05-04 07:44:21.955 2025-05-04 07:44:21.959467 :927AB23C:db_trace:kst.c@679:kstipg(): [10280:25:0] kst: process info: ospid=10952 pso_num=25 pso_serial#=92 2025-05-04 07:44:21.959613 :927AB23D:db_trace:kso.c@4093:ksonfy(): [10420:25:0] kso: new process: pid=10952 osp_idx=23 osp_ver=74551 osp_pg=0 (spawn #146717) 2025-05-04 07:44:21.959613 :927AB23E:db_trace:kso.c@4099:ksonfy(): [10420:25:0] kso: new process: first_req_pid=1236 spawner_pid=3660 sga_crt_ts=x8A8A 2025-05-04 07:44:21.959614 :927AB23F:db_trace:kso.c@4103:ksonfy(): [10420:25:0] kso: new process: pso_index=25 reservation=229 time=3615439125 2025-05-04 07:44:21.959614 :927AB240:db_trace:kso.c@4109:ksonfy(): [10420:25:0] kso: spawn diagnostics: queue time=0 secs 2025-05-04 07:44:21.959615 :927AB241:db_trace:kso.c@4111:ksonfy(): [10420:25:0] kso: spawn diagnostics: fork time=0 secs 2025-05-04 07:44:21.959615 :927AB242:db_trace:kso.c@4113:ksonfy(): [10420:25:0] kso: spawn diagnostics: exec time=0 secs 2025-05-04 07:44:21.959615 :927AB243:db_trace:kso.c@4115:ksonfy(): [10420:25:0] kso: spawn diagnostics: pre dbkc time=0 secs 2025-05-04 07:44:21.959616 :927AB244:db_trace:kso.c@4117:ksonfy(): [10420:25:0] kso: spawn diagnostics: post dbkc time=0 secs 2025-05-04 07:44:21.960120 :927AB245:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:25:201] KSL POST SENT postee=23 loc='kso2.h LINE:416 ID:ksoreq_reply' id1=0 id2=0 name= type=0 2025-05-04 07:44:21.960165 :927AB24C:db_trace:ksl2.c@12699:ksliwat(): [10005:25:201] KSL POST RCVD poster=23 loc='ksv2.h LINE:1639 ID:ksvpst: run' id1=0 id2=0 name= type=0 fac#=0 facpost=1 2025-05-04 07:54:20.381305 :927B7736:db_trace:ksl2.c@12699:ksliwat(): [10005:25:201] KSL POST RCVD poster=23 loc='ksl2.h LINE:2165 ID:kslpsr' id1=255 id2=0 name=EV type=0 fac#=0 facpost=1 2025-05-04 07:54:20.381341 :927B7737:db_trace:ksl2.c@2477:kslwtbctx(): [10005:25:201] KSL WAIT BEG [latch free] 136537728/0x8236680 259/0x103 0/0x0 wait_id=121 seq_num=122 snap_id=1 2025-05-04 07:54:20.381374 :927B773C:db_trace:ksl2.c@2611:kslwtectx(): [10005:25:201] KSL WAIT END [latch free] 136537728/0x8236680 259/0x103 0/0x0 wait_id=121 seq_num=122 snap_id=1 2025-05-04 07:54:20.381375 :927B773D:db_trace:ksl2.c@2619:kslwtectx(): [10005:25:201] KSL WAIT END wait times (usecs) - snap=33, exc=33, tot=33 2025-05-04 08:04:21.304864 :927C3ED5:db_trace:kst.c@698:kstpsodel(): [10280:25:0] kst: process state object about to be deleted 2025-05-04 08:04:21.668662 :927C3F3D:db_trace:kst.c@673:kstipg(): [10280:25:0] kst: process state object created on 05-04 08:04:21.664 2025-05-04 08:04:21.668664 :927C3F3E:db_trace:kst.c@679:kstipg(): [10280:25:0] kst: process info: ospid=10572 pso_num=25 pso_serial#=93 2025-05-04 08:04:21.668792 :927C3F3F:db_trace:kso.c@4093:ksonfy(): [10420:25:0] kso: new process: pid=10572 osp_idx=23 osp_ver=74552 osp_pg=0 (spawn #146767) 2025-05-04 08:04:21.668793 :927C3F40:db_trace:kso.c@4099:ksonfy(): [10420:25:0] kso: new process: first_req_pid=1236 spawner_pid=3660 sga_crt_ts=x8A8A 2025-05-04 08:04:21.668793 :927C3F41:db_trace:kso.c@4103:ksonfy(): [10420:25:0] kso: new process: pso_index=25 reservation=230 time=3616638828 2025-05-04 08:04:21.668793 :927C3F42:db_trace:kso.c@4109:ksonfy(): [10420:25:0] kso: spawn diagnostics: queue time=0 secs 2025-05-04 08:04:21.668794 :927C3F43:db_trace:kso.c@4111:ksonfy(): [10420:25:0] kso: spawn diagnostics: fork time=0 secs 2025-05-04 08:04:21.668794 :927C3F44:db_trace:kso.c@4113:ksonfy(): [10420:25:0] kso: spawn diagnostics: exec time=0 secs 2025-05-04 08:04:21.668795 :927C3F45:db_trace:kso.c@4115:ksonfy(): [10420:25:0] kso: spawn diagnostics: pre dbkc time=0 secs 2025-05-04 08:04:21.668795 :927C3F46:db_trace:kso.c@4117:ksonfy(): [10420:25:0] kso: spawn diagnostics: post dbkc time=0 secs 2025-05-04 08:04:21.669271 :927C3F47:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:25:201] KSL POST SENT postee=23 loc='kso2.h LINE:416 ID:ksoreq_reply' id1=0 id2=0 name= type=0 2025-05-04 08:04:21.669320 :927C3F4F:db_trace:ksl2.c@12699:ksliwat(): [10005:25:201] KSL POST RCVD poster=23 loc='ksv2.h LINE:1639 ID:ksvpst: run' id1=0 id2=0 name= type=0 fac#=0 facpost=1 2025-05-04 08:14:22.545393 :927D09EE:db_trace:kst.c@698:kstpsodel(): [10280:25:0] kst: process state object about to be deleted 2025-05-04 08:14:23.018583 :927D0A49:db_trace:kst.c@673:kstipg(): [10280:25:0] kst: process state object created on 05-04 08:14:23.014 2025-05-04 08:14:23.018585 :927D0A4A:db_trace:kst.c@679:kstipg(): [10280:25:0] kst: process info: ospid=3772 pso_num=25 pso_serial#=94 2025-05-04 08:14:23.018726 :927D0A4B:db_trace:kso.c@4093:ksonfy(): [10420:25:0] kso: new process: pid=3772 osp_idx=23 osp_ver=74553 osp_pg=0 (spawn #146789) 2025-05-04 08:14:23.018727 :927D0A4C:db_trace:kso.c@4099:ksonfy(): [10420:25:0] kso: new process: first_req_pid=1236 spawner_pid=3660 sga_crt_ts=x8A8A 2025-05-04 08:14:23.018727 :927D0A4D:db_trace:kso.c@4103:ksonfy(): [10420:25:0] kso: new process: pso_index=25 reservation=231 time=3617240187 2025-05-04 08:14:23.018728 :927D0A4E:db_trace:kso.c@4109:ksonfy(): [10420:25:0] kso: spawn diagnostics: queue time=0 secs 2025-05-04 08:14:23.018729 :927D0A4F:db_trace:kso.c@4111:ksonfy(): [10420:25:0] kso: spawn diagnostics: fork time=0 secs 2025-05-04 08:14:23.018729 :927D0A50:db_trace:kso.c@4113:ksonfy(): [10420:25:0] kso: spawn diagnostics: exec time=0 secs 2025-05-04 08:14:23.018729 :927D0A51:db_trace:kso.c@4115:ksonfy(): [10420:25:0] kso: spawn diagnostics: pre dbkc time=0 secs 2025-05-04 08:14:23.018730 :927D0A52:db_trace:kso.c@4117:ksonfy(): [10420:25:0] kso: spawn diagnostics: post dbkc time=0 secs 2025-05-04 08:14:23.019223 :927D0A53:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:25:201] KSL POST SENT postee=23 loc='kso2.h LINE:416 ID:ksoreq_reply' id1=0 id2=0 name= type=0 2025-05-04 08:14:23.019267 :927D0A5A:db_trace:ksl2.c@12699:ksliwat(): [10005:25:201] KSL POST RCVD poster=23 loc='ksv2.h LINE:1639 ID:ksvpst: run' id1=0 id2=0 name= type=0 fac#=0 facpost=1 ------------------------------------------------------------------------------- Trace Bucket Dump End: default bucket for process 25 (osid: 3772, W000)