Trace file d:\app\administrator\diag\rdbms\orcl\orcl\trace\cdmp_20250825081341\orcl_w000_20744_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:35219M/63366M, Ph+PgF:40300M/72582M Instance name: orcl Redo thread mounted by this instance: 1 Oracle process number: 22 Windows thread id: 20744, image: ORACLE.EXE (W000) *** 2025-08-25 08:13:41.885 *** SESSION ID:(177.53271) 2025-08-25 08:13:41.885 *** 2025-08-25 08:13:41.885 Process diagnostic dump for ORACLE.EXE (W000), OS id=20744, pid: 22, proc_ser: 241, sid: 177, sess_ser: 53271 ------------------------------------------------------------------------------- current sql: Current Wait Stack: 0: waiting for 'Space Manager: slave idle wait' Slave ID=0x0, =0x0, =0x0 wait_id=43 seq_num=44 snap_id=1 wait times: snap=1.547853 sec, exc=1.547853 sec, total=1.547853 sec wait times: max=5.000000 sec, heur=3 min 31 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.000025 sec since current wait 0: waited for 'Space Manager: slave idle wait' Slave ID=0x0, =0x0, =0x0 wait_id=42 seq_num=43 snap_id=1 wait times: snap=5.010145 sec, exc=5.010145 sec, total=5.010145 sec wait times: max=5.000000 sec wait counts: calls=1 os=1 occurred after 0.000026 sec of elapsed time 1: waited for 'Space Manager: slave idle wait' Slave ID=0x0, =0x0, =0x0 wait_id=41 seq_num=42 snap_id=1 wait times: snap=5.008335 sec, exc=5.008335 sec, total=5.008335 sec wait times: max=5.000000 sec wait counts: calls=1 os=1 occurred after 0.000021 sec of elapsed time 2: waited for 'Space Manager: slave idle wait' Slave ID=0x0, =0x0, =0x0 wait_id=40 seq_num=41 snap_id=1 wait times: snap=5.013324 sec, exc=5.013324 sec, total=5.013324 sec wait times: max=5.000000 sec wait counts: calls=1 os=1 occurred after 0.000024 sec of elapsed time 3: waited for 'Space Manager: slave idle wait' Slave ID=0x0, =0x0, =0x0 wait_id=39 seq_num=40 snap_id=1 wait times: snap=5.013523 sec, exc=5.013523 sec, total=5.013523 sec wait times: max=5.000000 sec wait counts: calls=1 os=1 occurred after 0.000023 sec of elapsed time 4: waited for 'Space Manager: slave idle wait' Slave ID=0x0, =0x0, =0x0 wait_id=38 seq_num=39 snap_id=1 wait times: snap=5.010171 sec, exc=5.010171 sec, total=5.010171 sec wait times: max=5.000000 sec wait counts: calls=1 os=1 occurred after 0.000021 sec of elapsed time 5: waited for 'Space Manager: slave idle wait' Slave ID=0x0, =0x0, =0x0 wait_id=37 seq_num=38 snap_id=1 wait times: snap=5.014766 sec, exc=5.014766 sec, total=5.014766 sec wait times: max=5.000000 sec wait counts: calls=1 os=1 occurred after 0.000022 sec of elapsed time 6: waited for 'Space Manager: slave idle wait' Slave ID=0x0, =0x0, =0x0 wait_id=36 seq_num=37 snap_id=1 wait times: snap=5.004620 sec, exc=5.004620 sec, total=5.004620 sec wait times: max=5.000000 sec wait counts: calls=1 os=1 occurred after 0.000026 sec of elapsed time 7: waited for 'Space Manager: slave idle wait' Slave ID=0x0, =0x0, =0x0 wait_id=35 seq_num=36 snap_id=1 wait times: snap=5.015249 sec, exc=5.015249 sec, total=5.015249 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=34 seq_num=35 snap_id=1 wait times: snap=5.003216 sec, exc=5.003216 sec, total=5.003216 sec wait times: max=5.000000 sec wait counts: calls=1 os=1 occurred after 0.000021 sec of elapsed time 9: waited for 'Space Manager: slave idle wait' Slave ID=0x0, =0x0, =0x0 wait_id=33 seq_num=34 snap_id=1 wait times: snap=5.011177 sec, exc=5.011177 sec, total=5.011177 sec wait times: max=5.000000 sec wait counts: calls=1 os=1 occurred after 0.000026 sec of elapsed time Sampled Session History of session 177 serial 53271 --------------------------------------------------- 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:11:41 - 08:13:41] idle wait at each sample ------------------------------------------------------------------------------- Process diagnostic dump actual duration=0.000000 sec (max dump time=30.000000 sec) *** 2025-08-25 08:13:41.885 ------------------------------------------------------------------------------- Trace Bucket Dump Begin: default bucket for process 22 (osid: 20744, W000) TIME(*=approx):SEQ:COMPONENT:FILE@LINE:FUNCTION:SECT/DUMP: [EVENT#:PID:SID] DATA ------------------------------------------------------------------------------- 2025-08-25 05:59:46.498257 :C455895D:db_trace:kst.c@698:kstpsodel(): [10280:22:0] kst: process state object about to be deleted 2025-08-25 05:59:47.557198 :C4558992:db_trace:kst.c@673:kstipg(): [10280:22:0] kst: process state object created on 08-25 05:59:47.544 2025-08-25 05:59:47.557200 :C4558993:db_trace:kst.c@679:kstipg(): [10280:22:0] kst: process info: ospid=21672 pso_num=22 pso_serial#=227 2025-08-25 05:59:47.557372 :C4558994:db_trace:kso.c@4070:ksonfy(): [10420:22:0] kso: new process: pid=21672 (legacy spawn) 2025-08-25 05:59:47.563839 :C4558995:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:22:177] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-08-25 05:59:47.564006 :C455899A:db_trace:ksl2.c@12699:ksliwat(): [10005:22:177] 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-08-25 05:59:47.564808 :C455899F:db_trace:kst.c@698:kstpsodel(): [10280:22:0] kst: process state object about to be deleted 2025-08-25 05:59:47.573498 :C45589A2:db_trace:kst.c@673:kstipg(): [10280:22:0] kst: process state object created on 08-25 05:59:47.560 2025-08-25 05:59:47.573500 :C45589A3:db_trace:kst.c@679:kstipg(): [10280:22:0] kst: process info: ospid=18048 pso_num=22 pso_serial#=228 2025-08-25 05:59:47.573636 :C45589A4:db_trace:kso.c@4070:ksonfy(): [10420:22:0] kso: new process: pid=18048 (legacy spawn) 2025-08-25 05:59:47.580164 :C45589A5:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:22:177] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-08-25 05:59:47.580326 :C45589AE:db_trace:ksl2.c@12699:ksliwat(): [10005:22:177] 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-08-25 05:59:47.581108 :C45589AF:db_trace:kst.c@698:kstpsodel(): [10280:22:0] kst: process state object about to be deleted 2025-08-25 05:59:53.413283 :C4558B88:db_trace:kst.c@673:kstipg(): [10280:22:0] kst: process state object created on 08-25 05:59:53.408 2025-08-25 05:59:53.413286 :C4558B89:db_trace:kst.c@679:kstipg(): [10280:22:0] kst: process info: ospid=22792 pso_num=22 pso_serial#=229 2025-08-25 05:59:53.413424 :C4558B8A:db_trace:kso.c@4093:ksonfy(): [10420:22:0] kso: new process: pid=22792 osp_idx=0 osp_ver=547021 osp_pg=0 (spawn #523599) 2025-08-25 05:59:53.413424 :C4558B8B:db_trace:kso.c@4099:ksonfy(): [10420:22:0] kso: new process: first_req_pid=1236 spawner_pid=3660 sga_crt_ts=x8A8A 2025-08-25 05:59:53.413425 :C4558B8C:db_trace:kso.c@4103:ksonfy(): [10420:22:0] kso: new process: pso_index=22 reservation=223 time=487248158 2025-08-25 05:59:53.413425 :C4558B8D:db_trace:kso.c@4109:ksonfy(): [10420:22:0] kso: spawn diagnostics: queue time=0 secs 2025-08-25 05:59:53.413425 :C4558B8E:db_trace:kso.c@4111:ksonfy(): [10420:22:0] kso: spawn diagnostics: fork time=0 secs 2025-08-25 05:59:53.413426 :C4558B8F:db_trace:kso.c@4113:ksonfy(): [10420:22:0] kso: spawn diagnostics: exec time=0 secs 2025-08-25 05:59:53.413426 :C4558B90:db_trace:kso.c@4115:ksonfy(): [10420:22:0] kso: spawn diagnostics: pre dbkc time=0 secs 2025-08-25 05:59:53.413426 :C4558B91:db_trace:kso.c@4117:ksonfy(): [10420:22:0] kso: spawn diagnostics: post dbkc time=0 secs 2025-08-25 05:59:53.413907 :C4558B92:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:22:177] KSL POST SENT postee=23 loc='kso2.h LINE:416 ID:ksoreq_reply' id1=0 id2=0 name= type=0 2025-08-25 05:59:53.413952 :C4558B99:db_trace:ksl2.c@12699:ksliwat(): [10005:22:177] 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-08-25 06:09:54.400697 :C4565752:db_trace:kst.c@698:kstpsodel(): [10280:22:0] kst: process state object about to be deleted 2025-08-25 06:09:54.842981 :C4565785:db_trace:kst.c@673:kstipg(): [10280:22:0] kst: process state object created on 08-25 06:09:54.838 2025-08-25 06:09:54.842983 :C4565786:db_trace:kst.c@679:kstipg(): [10280:22:0] kst: process info: ospid=1388 pso_num=22 pso_serial#=230 2025-08-25 06:09:54.843127 :C4565787:db_trace:kso.c@4093:ksonfy(): [10420:22:0] kso: new process: pid=1388 osp_idx=0 osp_ver=547022 osp_pg=0 (spawn #523624) 2025-08-25 06:09:54.843127 :C4565788:db_trace:kso.c@4099:ksonfy(): [10420:22:0] kso: new process: first_req_pid=1236 spawner_pid=3660 sga_crt_ts=x8A8A 2025-08-25 06:09:54.843128 :C4565789:db_trace:kso.c@4103:ksonfy(): [10420:22:0] kso: new process: pso_index=22 reservation=224 time=487849580 2025-08-25 06:09:54.843128 :C456578A:db_trace:kso.c@4109:ksonfy(): [10420:22:0] kso: spawn diagnostics: queue time=0 secs 2025-08-25 06:09:54.843129 :C456578B:db_trace:kso.c@4111:ksonfy(): [10420:22:0] kso: spawn diagnostics: fork time=0 secs 2025-08-25 06:09:54.843129 :C456578C:db_trace:kso.c@4113:ksonfy(): [10420:22:0] kso: spawn diagnostics: exec time=0 secs 2025-08-25 06:09:54.843129 :C456578D:db_trace:kso.c@4115:ksonfy(): [10420:22:0] kso: spawn diagnostics: pre dbkc time=0 secs 2025-08-25 06:09:54.843130 :C456578E:db_trace:kso.c@4117:ksonfy(): [10420:22:0] kso: spawn diagnostics: post dbkc time=0 secs 2025-08-25 06:09:54.843626 :C456578F:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:22:177] KSL POST SENT postee=23 loc='kso2.h LINE:416 ID:ksoreq_reply' id1=0 id2=0 name= type=0 2025-08-25 06:09:54.843672 :C4565799:db_trace:ksl2.c@12699:ksliwat(): [10005:22:177] 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-08-25 06:19:55.736718 :C4571908:db_trace:kst.c@698:kstpsodel(): [10280:22:0] kst: process state object about to be deleted 2025-08-25 06:19:56.116482 :C457194D:db_trace:kst.c@673:kstipg(): [10280:22:0] kst: process state object created on 08-25 06:19:56.111 2025-08-25 06:19:56.116484 :C457194E:db_trace:kst.c@679:kstipg(): [10280:22:0] kst: process info: ospid=17416 pso_num=22 pso_serial#=231 2025-08-25 06:19:56.116624 :C457194F:db_trace:kso.c@4093:ksonfy(): [10420:22:0] kso: new process: pid=17416 osp_idx=0 osp_ver=547023 osp_pg=0 (spawn #523647) 2025-08-25 06:19:56.116625 :C4571950:db_trace:kso.c@4099:ksonfy(): [10420:22:0] kso: new process: first_req_pid=1236 spawner_pid=3660 sga_crt_ts=x8A8A 2025-08-25 06:19:56.116625 :C4571951:db_trace:kso.c@4103:ksonfy(): [10420:22:0] kso: new process: pso_index=22 reservation=225 time=488450862 2025-08-25 06:19:56.116625 :C4571952:db_trace:kso.c@4109:ksonfy(): [10420:22:0] kso: spawn diagnostics: queue time=0 secs 2025-08-25 06:19:56.116626 :C4571953:db_trace:kso.c@4111:ksonfy(): [10420:22:0] kso: spawn diagnostics: fork time=0 secs 2025-08-25 06:19:56.116626 :C4571954:db_trace:kso.c@4113:ksonfy(): [10420:22:0] kso: spawn diagnostics: exec time=0 secs 2025-08-25 06:19:56.116627 :C4571955:db_trace:kso.c@4115:ksonfy(): [10420:22:0] kso: spawn diagnostics: pre dbkc time=0 secs 2025-08-25 06:19:56.116627 :C4571956:db_trace:kso.c@4117:ksonfy(): [10420:22:0] kso: spawn diagnostics: post dbkc time=0 secs 2025-08-25 06:19:56.117145 :C4571957:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:22:177] KSL POST SENT postee=23 loc='kso2.h LINE:416 ID:ksoreq_reply' id1=0 id2=0 name= type=0 2025-08-25 06:19:56.117187 :C457195F:db_trace:ksl2.c@12699:ksliwat(): [10005:22:177] 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-08-25 06:29:57.023341 :C457DA0E:db_trace:kst.c@698:kstpsodel(): [10280:22:0] kst: process state object about to be deleted 2025-08-25 06:29:57.371920 :C457DA40:db_trace:kst.c@673:kstipg(): [10280:22:0] kst: process state object created on 08-25 06:29:57.367 2025-08-25 06:29:57.371922 :C457DA41:db_trace:kst.c@679:kstipg(): [10280:22:0] kst: process info: ospid=21580 pso_num=22 pso_serial#=232 2025-08-25 06:29:57.372064 :C457DA42:db_trace:kso.c@4093:ksonfy(): [10420:22:0] kso: new process: pid=21580 osp_idx=0 osp_ver=547024 osp_pg=0 (spawn #523670) 2025-08-25 06:29:57.372064 :C457DA43:db_trace:kso.c@4099:ksonfy(): [10420:22:0] kso: new process: first_req_pid=1236 spawner_pid=3660 sga_crt_ts=x8A8A 2025-08-25 06:29:57.372065 :C457DA44:db_trace:kso.c@4103:ksonfy(): [10420:22:0] kso: new process: pso_index=22 reservation=226 time=489052112 2025-08-25 06:29:57.372065 :C457DA45:db_trace:kso.c@4109:ksonfy(): [10420:22:0] kso: spawn diagnostics: queue time=0 secs 2025-08-25 06:29:57.372065 :C457DA46:db_trace:kso.c@4111:ksonfy(): [10420:22:0] kso: spawn diagnostics: fork time=0 secs 2025-08-25 06:29:57.372066 :C457DA47:db_trace:kso.c@4113:ksonfy(): [10420:22:0] kso: spawn diagnostics: exec time=0 secs 2025-08-25 06:29:57.372066 :C457DA48:db_trace:kso.c@4115:ksonfy(): [10420:22:0] kso: spawn diagnostics: pre dbkc time=0 secs 2025-08-25 06:29:57.372066 :C457DA49:db_trace:kso.c@4117:ksonfy(): [10420:22:0] kso: spawn diagnostics: post dbkc time=0 secs 2025-08-25 06:29:57.372560 :C457DA4A:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:22:177] KSL POST SENT postee=23 loc='kso2.h LINE:416 ID:ksoreq_reply' id1=0 id2=0 name= type=0 2025-08-25 06:29:57.372603 :C457DA52:db_trace:ksl2.c@12699:ksliwat(): [10005:22:177] 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-08-25 06:39:58.293029 :C4589C52:db_trace:kst.c@698:kstpsodel(): [10280:22:0] kst: process state object about to be deleted 2025-08-25 06:39:58.610322 :C4589C99:db_trace:kst.c@673:kstipg(): [10280:22:0] kst: process state object created on 08-25 06:39:58.606 2025-08-25 06:39:58.610324 :C4589C9A:db_trace:kst.c@679:kstipg(): [10280:22:0] kst: process info: ospid=23416 pso_num=22 pso_serial#=233 2025-08-25 06:39:58.610463 :C4589C9B:db_trace:kso.c@4093:ksonfy(): [10420:22:0] kso: new process: pid=23416 osp_idx=0 osp_ver=547025 osp_pg=0 (spawn #523692) 2025-08-25 06:39:58.610464 :C4589C9C:db_trace:kso.c@4099:ksonfy(): [10420:22:0] kso: new process: first_req_pid=1236 spawner_pid=3660 sga_crt_ts=x8A8A 2025-08-25 06:39:58.610465 :C4589C9D:db_trace:kso.c@4103:ksonfy(): [10420:22:0] kso: new process: pso_index=22 reservation=227 time=489653346 2025-08-25 06:39:58.610465 :C4589C9E:db_trace:kso.c@4109:ksonfy(): [10420:22:0] kso: spawn diagnostics: queue time=0 secs 2025-08-25 06:39:58.610466 :C4589C9F:db_trace:kso.c@4111:ksonfy(): [10420:22:0] kso: spawn diagnostics: fork time=0 secs 2025-08-25 06:39:58.610466 :C4589CA0:db_trace:kso.c@4113:ksonfy(): [10420:22:0] kso: spawn diagnostics: exec time=0 secs 2025-08-25 06:39:58.610466 :C4589CA1:db_trace:kso.c@4115:ksonfy(): [10420:22:0] kso: spawn diagnostics: pre dbkc time=0 secs 2025-08-25 06:39:58.610467 :C4589CA2:db_trace:kso.c@4117:ksonfy(): [10420:22:0] kso: spawn diagnostics: post dbkc time=0 secs 2025-08-25 06:39:58.610974 :C4589CA3:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:22:177] KSL POST SENT postee=23 loc='kso2.h LINE:416 ID:ksoreq_reply' id1=0 id2=0 name= type=0 2025-08-25 06:39:58.611026 :C4589CAB:db_trace:ksl2.c@12699:ksliwat(): [10005:22:177] 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-08-25 06:49:59.452088 :C4595F44:db_trace:kst.c@698:kstpsodel(): [10280:22:0] kst: process state object about to be deleted 2025-08-25 06:49:59.805615 :C4595F76:db_trace:kst.c@673:kstipg(): [10280:22:0] kst: process state object created on 08-25 06:49:59.800 2025-08-25 06:49:59.805617 :C4595F77:db_trace:kst.c@679:kstipg(): [10280:22:0] kst: process info: ospid=22820 pso_num=22 pso_serial#=234 2025-08-25 06:49:59.805750 :C4595F78:db_trace:kso.c@4093:ksonfy(): [10420:22:0] kso: new process: pid=22820 osp_idx=0 osp_ver=547026 osp_pg=0 (spawn #523715) 2025-08-25 06:49:59.805751 :C4595F79:db_trace:kso.c@4099:ksonfy(): [10420:22:0] kso: new process: first_req_pid=1236 spawner_pid=3660 sga_crt_ts=x8A8A 2025-08-25 06:49:59.805751 :C4595F7A:db_trace:kso.c@4103:ksonfy(): [10420:22:0] kso: new process: pso_index=22 reservation=228 time=490254549 2025-08-25 06:49:59.805751 :C4595F7B:db_trace:kso.c@4109:ksonfy(): [10420:22:0] kso: spawn diagnostics: queue time=0 secs 2025-08-25 06:49:59.805752 :C4595F7C:db_trace:kso.c@4111:ksonfy(): [10420:22:0] kso: spawn diagnostics: fork time=0 secs 2025-08-25 06:49:59.805752 :C4595F7D:db_trace:kso.c@4113:ksonfy(): [10420:22:0] kso: spawn diagnostics: exec time=0 secs 2025-08-25 06:49:59.805752 :C4595F7E:db_trace:kso.c@4115:ksonfy(): [10420:22:0] kso: spawn diagnostics: pre dbkc time=0 secs 2025-08-25 06:49:59.805753 :C4595F7F:db_trace:kso.c@4117:ksonfy(): [10420:22:0] kso: spawn diagnostics: post dbkc time=0 secs 2025-08-25 06:49:59.806254 :C4595F80:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:22:177] KSL POST SENT postee=23 loc='kso2.h LINE:416 ID:ksoreq_reply' id1=0 id2=0 name= type=0 2025-08-25 06:49:59.806299 :C4595F88:db_trace:ksl2.c@12699:ksliwat(): [10005:22:177] 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-08-25 07:00:00.687844 :C45A2058:db_trace:kst.c@698:kstpsodel(): [10280:22:0] kst: process state object about to be deleted 2025-08-25 07:00:01.083347 :C45A20A1:db_trace:kst.c@673:kstipg(): [10280:22:0] kst: process state object created on 08-25 07:00:01.078 2025-08-25 07:00:01.083350 :C45A20A2:db_trace:kst.c@679:kstipg(): [10280:22:0] kst: process info: ospid=8216 pso_num=22 pso_serial#=235 2025-08-25 07:00:01.083490 :C45A20A3:db_trace:kso.c@4093:ksonfy(): [10420:22:0] kso: new process: pid=8216 osp_idx=0 osp_ver=547027 osp_pg=0 (spawn #523738) 2025-08-25 07:00:01.083491 :C45A20A4:db_trace:kso.c@4099:ksonfy(): [10420:22:0] kso: new process: first_req_pid=1236 spawner_pid=3660 sga_crt_ts=x8A8A 2025-08-25 07:00:01.083491 :C45A20A5:db_trace:kso.c@4103:ksonfy(): [10420:22:0] kso: new process: pso_index=22 reservation=229 time=490855815 2025-08-25 07:00:01.083492 :C45A20A6:db_trace:kso.c@4109:ksonfy(): [10420:22:0] kso: spawn diagnostics: queue time=0 secs 2025-08-25 07:00:01.083492 :C45A20A7:db_trace:kso.c@4111:ksonfy(): [10420:22:0] kso: spawn diagnostics: fork time=0 secs 2025-08-25 07:00:01.083492 :C45A20A8:db_trace:kso.c@4113:ksonfy(): [10420:22:0] kso: spawn diagnostics: exec time=0 secs 2025-08-25 07:00:01.083493 :C45A20A9:db_trace:kso.c@4115:ksonfy(): [10420:22:0] kso: spawn diagnostics: pre dbkc time=0 secs 2025-08-25 07:00:01.083493 :C45A20AA:db_trace:kso.c@4117:ksonfy(): [10420:22:0] kso: spawn diagnostics: post dbkc time=0 secs 2025-08-25 07:00:01.084036 :C45A20AB:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:22:177] KSL POST SENT postee=23 loc='kso2.h LINE:416 ID:ksoreq_reply' id1=0 id2=0 name= type=0 2025-08-25 07:00:01.084086 :C45A20B3:db_trace:ksl2.c@12699:ksliwat(): [10005:22:177] 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-08-25 07:10:01.990687 :C45AEB79:db_trace:kst.c@698:kstpsodel(): [10280:22:0] kst: process state object about to be deleted 2025-08-25 07:10:02.427395 :C45AEBE7:db_trace:kst.c@673:kstipg(): [10280:22:0] kst: process state object created on 08-25 07:10:02.422 2025-08-25 07:10:02.427397 :C45AEBE8:db_trace:kst.c@679:kstipg(): [10280:22:0] kst: process info: ospid=22820 pso_num=22 pso_serial#=236 2025-08-25 07:10:02.427531 :C45AEBE9:db_trace:kso.c@4093:ksonfy(): [10420:22:0] kso: new process: pid=22820 osp_idx=0 osp_ver=547028 osp_pg=0 (spawn #523763) 2025-08-25 07:10:02.427531 :C45AEBEA:db_trace:kso.c@4099:ksonfy(): [10420:22:0] kso: new process: first_req_pid=1236 spawner_pid=3660 sga_crt_ts=x8A8A 2025-08-25 07:10:02.427532 :C45AEBEB:db_trace:kso.c@4103:ksonfy(): [10420:22:0] kso: new process: pso_index=22 reservation=230 time=491457158 2025-08-25 07:10:02.427532 :C45AEBEC:db_trace:kso.c@4109:ksonfy(): [10420:22:0] kso: spawn diagnostics: queue time=0 secs 2025-08-25 07:10:02.427533 :C45AEBED:db_trace:kso.c@4111:ksonfy(): [10420:22:0] kso: spawn diagnostics: fork time=0 secs 2025-08-25 07:10:02.427533 :C45AEBEE:db_trace:kso.c@4113:ksonfy(): [10420:22:0] kso: spawn diagnostics: exec time=0 secs 2025-08-25 07:10:02.427533 :C45AEBEF:db_trace:kso.c@4115:ksonfy(): [10420:22:0] kso: spawn diagnostics: pre dbkc time=0 secs 2025-08-25 07:10:02.427534 :C45AEBF0:db_trace:kso.c@4117:ksonfy(): [10420:22:0] kso: spawn diagnostics: post dbkc time=0 secs 2025-08-25 07:10:02.428009 :C45AEBF1:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:22:177] KSL POST SENT postee=23 loc='kso2.h LINE:416 ID:ksoreq_reply' id1=0 id2=0 name= type=0 2025-08-25 07:10:02.428061 :C45AEBFB:db_trace:ksl2.c@12699:ksliwat(): [10005:22:177] 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-08-25 07:11:02.527998 :C45AFFA7:db_trace:ksl2.c@2477:kslwtbctx(): [10005:22:177] KSL WAIT BEG [latch free] 136537728/0x8236680 259/0x103 0/0x0 wait_id=13 seq_num=14 snap_id=1 2025-08-25 07:11:02.528029 :C45AFFAC:db_trace:ksl2.c@2611:kslwtectx(): [10005:22:177] KSL WAIT END [latch free] 136537728/0x8236680 259/0x103 0/0x0 wait_id=13 seq_num=14 snap_id=1 2025-08-25 07:11:02.528030 :C45AFFAD:db_trace:ksl2.c@2619:kslwtectx(): [10005:22:177] KSL WAIT END wait times (usecs) - snap=30, exc=30, tot=30 2025-08-25 07:15:11.052723 :C45B5009:db_trace:ksl2.c@12699:ksliwat(): [10005:22:177] 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-08-25 07:20:03.721013 :C45BADC8:db_trace:ksl2.c@12699:ksliwat(): [10005:22:177] 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-08-25 07:30:04.651690 :C45C721C:db_trace:kst.c@698:kstpsodel(): [10280:22:0] kst: process state object about to be deleted 2025-08-25 07:30:05.015734 :C45C7284:db_trace:kst.c@673:kstipg(): [10280:22:0] kst: process state object created on 08-25 07:30:05.011 2025-08-25 07:30:05.015736 :C45C7285:db_trace:kst.c@679:kstipg(): [10280:22:0] kst: process info: ospid=22908 pso_num=22 pso_serial#=237 2025-08-25 07:30:05.015872 :C45C7286:db_trace:kso.c@4093:ksonfy(): [10420:22:0] kso: new process: pid=22908 osp_idx=0 osp_ver=547029 osp_pg=0 (spawn #523808) 2025-08-25 07:30:05.015872 :C45C7287:db_trace:kso.c@4099:ksonfy(): [10420:22:0] kso: new process: first_req_pid=1236 spawner_pid=3660 sga_crt_ts=x8A8A 2025-08-25 07:30:05.015873 :C45C7288:db_trace:kso.c@4103:ksonfy(): [10420:22:0] kso: new process: pso_index=22 reservation=231 time=492659752 2025-08-25 07:30:05.015873 :C45C7289:db_trace:kso.c@4109:ksonfy(): [10420:22:0] kso: spawn diagnostics: queue time=0 secs 2025-08-25 07:30:05.015873 :C45C728A:db_trace:kso.c@4111:ksonfy(): [10420:22:0] kso: spawn diagnostics: fork time=0 secs 2025-08-25 07:30:05.015874 :C45C728B:db_trace:kso.c@4113:ksonfy(): [10420:22:0] kso: spawn diagnostics: exec time=0 secs 2025-08-25 07:30:05.015874 :C45C728C:db_trace:kso.c@4115:ksonfy(): [10420:22:0] kso: spawn diagnostics: pre dbkc time=0 secs 2025-08-25 07:30:05.015874 :C45C728D:db_trace:kso.c@4117:ksonfy(): [10420:22:0] kso: spawn diagnostics: post dbkc time=0 secs 2025-08-25 07:30:05.016367 :C45C728E:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:22:177] KSL POST SENT postee=23 loc='kso2.h LINE:416 ID:ksoreq_reply' id1=0 id2=0 name= type=0 2025-08-25 07:30:05.016416 :C45C7298:db_trace:ksl2.c@12699:ksliwat(): [10005:22:177] 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-08-25 07:40:05.838278 :C45D33AD:db_trace:kst.c@698:kstpsodel(): [10280:22:0] kst: process state object about to be deleted 2025-08-25 07:40:06.217980 :C45D33E2:db_trace:kst.c@673:kstipg(): [10280:22:0] kst: process state object created on 08-25 07:40:06.213 2025-08-25 07:40:06.217982 :C45D33E3:db_trace:kst.c@679:kstipg(): [10280:22:0] kst: process info: ospid=20496 pso_num=22 pso_serial#=238 2025-08-25 07:40:06.218125 :C45D33E4:db_trace:kso.c@4093:ksonfy(): [10420:22:0] kso: new process: pid=20496 osp_idx=0 osp_ver=547030 osp_pg=0 (spawn #523830) 2025-08-25 07:40:06.218126 :C45D33E5:db_trace:kso.c@4099:ksonfy(): [10420:22:0] kso: new process: first_req_pid=1236 spawner_pid=3660 sga_crt_ts=x8A8A 2025-08-25 07:40:06.218126 :C45D33E6:db_trace:kso.c@4103:ksonfy(): [10420:22:0] kso: new process: pso_index=22 reservation=232 time=493260955 2025-08-25 07:40:06.218126 :C45D33E7:db_trace:kso.c@4109:ksonfy(): [10420:22:0] kso: spawn diagnostics: queue time=0 secs 2025-08-25 07:40:06.218126 :C45D33E8:db_trace:kso.c@4111:ksonfy(): [10420:22:0] kso: spawn diagnostics: fork time=0 secs 2025-08-25 07:40:06.218127 :C45D33E9:db_trace:kso.c@4113:ksonfy(): [10420:22:0] kso: spawn diagnostics: exec time=0 secs 2025-08-25 07:40:06.218127 :C45D33EA:db_trace:kso.c@4115:ksonfy(): [10420:22:0] kso: spawn diagnostics: pre dbkc time=0 secs 2025-08-25 07:40:06.218127 :C45D33EB:db_trace:kso.c@4117:ksonfy(): [10420:22:0] kso: spawn diagnostics: post dbkc time=0 secs 2025-08-25 07:40:06.218628 :C45D33EC:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:22:177] KSL POST SENT postee=23 loc='kso2.h LINE:416 ID:ksoreq_reply' id1=0 id2=0 name= type=0 2025-08-25 07:40:06.218674 :C45D33F4:db_trace:ksl2.c@12699:ksliwat(): [10005:22:177] 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-08-25 07:50:07.077954 :C45DF59F:db_trace:kst.c@698:kstpsodel(): [10280:22:0] kst: process state object about to be deleted 2025-08-25 07:50:07.504721 :C45DF5E5:db_trace:kst.c@673:kstipg(): [10280:22:0] kst: process state object created on 08-25 07:50:07.500 2025-08-25 07:50:07.504723 :C45DF5E6:db_trace:kst.c@679:kstipg(): [10280:22:0] kst: process info: ospid=16544 pso_num=22 pso_serial#=239 2025-08-25 07:50:07.504876 :C45DF5E7:db_trace:kso.c@4093:ksonfy(): [10420:22:0] kso: new process: pid=16544 osp_idx=0 osp_ver=547031 osp_pg=0 (spawn #523853) 2025-08-25 07:50:07.504877 :C45DF5E8:db_trace:kso.c@4099:ksonfy(): [10420:22:0] kso: new process: first_req_pid=1236 spawner_pid=3660 sga_crt_ts=x8A8A 2025-08-25 07:50:07.504877 :C45DF5E9:db_trace:kso.c@4103:ksonfy(): [10420:22:0] kso: new process: pso_index=22 reservation=233 time=493862237 2025-08-25 07:50:07.504878 :C45DF5EA:db_trace:kso.c@4109:ksonfy(): [10420:22:0] kso: spawn diagnostics: queue time=0 secs 2025-08-25 07:50:07.504878 :C45DF5EB:db_trace:kso.c@4111:ksonfy(): [10420:22:0] kso: spawn diagnostics: fork time=0 secs 2025-08-25 07:50:07.504879 :C45DF5EC:db_trace:kso.c@4113:ksonfy(): [10420:22:0] kso: spawn diagnostics: exec time=0 secs 2025-08-25 07:50:07.504879 :C45DF5ED:db_trace:kso.c@4115:ksonfy(): [10420:22:0] kso: spawn diagnostics: pre dbkc time=0 secs 2025-08-25 07:50:07.504879 :C45DF5EE:db_trace:kso.c@4117:ksonfy(): [10420:22:0] kso: spawn diagnostics: post dbkc time=0 secs 2025-08-25 07:50:07.505382 :C45DF5EF:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:22:177] KSL POST SENT postee=23 loc='kso2.h LINE:416 ID:ksoreq_reply' id1=0 id2=0 name= type=0 2025-08-25 07:50:07.505430 :C45DF5F7:db_trace:ksl2.c@12699:ksliwat(): [10005:22:177] 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-08-25 08:00:08.386106 :C45EB74F:db_trace:kst.c@698:kstpsodel(): [10280:22:0] kst: process state object about to be deleted 2025-08-25 08:00:08.687490 :C45EB785:db_trace:kst.c@673:kstipg(): [10280:22:0] kst: process state object created on 08-25 08:00:08.683 2025-08-25 08:00:08.687492 :C45EB786:db_trace:kst.c@679:kstipg(): [10280:22:0] kst: process info: ospid=21600 pso_num=22 pso_serial#=240 2025-08-25 08:00:08.687636 :C45EB787:db_trace:kso.c@4093:ksonfy(): [10420:22:0] kso: new process: pid=21600 osp_idx=0 osp_ver=547032 osp_pg=0 (spawn #523876) 2025-08-25 08:00:08.687636 :C45EB788:db_trace:kso.c@4099:ksonfy(): [10420:22:0] kso: new process: first_req_pid=1236 spawner_pid=3660 sga_crt_ts=x8A8A 2025-08-25 08:00:08.687637 :C45EB789:db_trace:kso.c@4103:ksonfy(): [10420:22:0] kso: new process: pso_index=22 reservation=234 time=494463424 2025-08-25 08:00:08.687637 :C45EB78A:db_trace:kso.c@4109:ksonfy(): [10420:22:0] kso: spawn diagnostics: queue time=0 secs 2025-08-25 08:00:08.687638 :C45EB78B:db_trace:kso.c@4111:ksonfy(): [10420:22:0] kso: spawn diagnostics: fork time=0 secs 2025-08-25 08:00:08.687638 :C45EB78C:db_trace:kso.c@4113:ksonfy(): [10420:22:0] kso: spawn diagnostics: exec time=0 secs 2025-08-25 08:00:08.687638 :C45EB78D:db_trace:kso.c@4115:ksonfy(): [10420:22:0] kso: spawn diagnostics: pre dbkc time=0 secs 2025-08-25 08:00:08.687639 :C45EB78E:db_trace:kso.c@4117:ksonfy(): [10420:22:0] kso: spawn diagnostics: post dbkc time=0 secs 2025-08-25 08:00:08.688131 :C45EB78F:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:22:177] KSL POST SENT postee=23 loc='kso2.h LINE:416 ID:ksoreq_reply' id1=0 id2=0 name= type=0 2025-08-25 08:00:08.688178 :C45EB797:db_trace:ksl2.c@12699:ksliwat(): [10005:22:177] 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-08-25 08:10:09.679867 :C45F8307:db_trace:kst.c@698:kstpsodel(): [10280:22:0] kst: process state object about to be deleted 2025-08-25 08:10:10.075351 :C45F835B:db_trace:kst.c@673:kstipg(): [10280:22:0] kst: process state object created on 08-25 08:10:10.070 2025-08-25 08:10:10.075353 :C45F835C:db_trace:kst.c@679:kstipg(): [10280:22:0] kst: process info: ospid=20744 pso_num=22 pso_serial#=241 2025-08-25 08:10:10.075501 :C45F835D:db_trace:kso.c@4093:ksonfy(): [10420:22:0] kso: new process: pid=20744 osp_idx=0 osp_ver=547033 osp_pg=0 (spawn #523901) 2025-08-25 08:10:10.075502 :C45F835E:db_trace:kso.c@4099:ksonfy(): [10420:22:0] kso: new process: first_req_pid=1236 spawner_pid=3660 sga_crt_ts=x8A8A 2025-08-25 08:10:10.075503 :C45F835F:db_trace:kso.c@4103:ksonfy(): [10420:22:0] kso: new process: pso_index=22 reservation=235 time=495064815 2025-08-25 08:10:10.075503 :C45F8360:db_trace:kso.c@4109:ksonfy(): [10420:22:0] kso: spawn diagnostics: queue time=0 secs 2025-08-25 08:10:10.075504 :C45F8361:db_trace:kso.c@4111:ksonfy(): [10420:22:0] kso: spawn diagnostics: fork time=0 secs 2025-08-25 08:10:10.075504 :C45F8362:db_trace:kso.c@4113:ksonfy(): [10420:22:0] kso: spawn diagnostics: exec time=0 secs 2025-08-25 08:10:10.075504 :C45F8363:db_trace:kso.c@4115:ksonfy(): [10420:22:0] kso: spawn diagnostics: pre dbkc time=0 secs 2025-08-25 08:10:10.075505 :C45F8364:db_trace:kso.c@4117:ksonfy(): [10420:22:0] kso: spawn diagnostics: post dbkc time=0 secs 2025-08-25 08:10:10.076026 :C45F8365:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:22:177] KSL POST SENT postee=23 loc='kso2.h LINE:416 ID:ksoreq_reply' id1=0 id2=0 name= type=0 2025-08-25 08:10:10.076070 :C45F836C:db_trace:ksl2.c@12699:ksliwat(): [10005:22:177] 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 22 (osid: 20744, W000)