Trace file d:\app\administrator\diag\rdbms\orcl\orcl\trace\cdmp_20250510220153\orcl_w000_10024_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:37492M/63366M, Ph+PgF:44864M/72582M Instance name: orcl Redo thread mounted by this instance: 1 Oracle process number: 22 Windows thread id: 10024, image: ORACLE.EXE (W000) *** 2025-05-10 22:01:53.760 *** SESSION ID:(177.21209) 2025-05-10 22:01:53.760 *** 2025-05-10 22:01:53.760 Process diagnostic dump for ORACLE.EXE (W000), OS id=10024, pid: 22, proc_ser: 203, sid: 177, sess_ser: 21209 ------------------------------------------------------------------------------- current sql: Current Wait Stack: 0: waiting for 'Space Manager: slave idle wait' Slave ID=0x0, =0x0, =0x0 wait_id=80 seq_num=81 snap_id=1 wait times: snap=1.148232 sec, exc=1.148232 sec, total=1.148232 sec wait times: max=5.000000 sec, heur=6 min 36 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.000035 sec since current wait 0: waited for 'Space Manager: slave idle wait' Slave ID=0x0, =0x0, =0x0 wait_id=79 seq_num=80 snap_id=1 wait times: snap=5.012726 sec, exc=5.012726 sec, total=5.012726 sec wait times: max=5.000000 sec wait counts: calls=1 os=1 occurred after 0.000027 sec of elapsed time 1: waited for 'Space Manager: slave idle wait' Slave ID=0x0, =0x0, =0x0 wait_id=78 seq_num=79 snap_id=1 wait times: snap=5.015072 sec, exc=5.015072 sec, total=5.015072 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=77 seq_num=78 snap_id=1 wait times: snap=5.004638 sec, exc=5.004638 sec, total=5.004638 sec wait times: max=5.000000 sec wait counts: calls=1 os=1 occurred after 0.000026 sec of elapsed time 3: waited for 'Space Manager: slave idle wait' Slave ID=0x0, =0x0, =0x0 wait_id=76 seq_num=77 snap_id=1 wait times: snap=5.004621 sec, exc=5.004621 sec, total=5.004621 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=75 seq_num=76 snap_id=1 wait times: snap=5.014761 sec, exc=5.014761 sec, total=5.014761 sec wait times: max=5.000000 sec wait counts: calls=1 os=1 occurred after 0.000025 sec of elapsed time 5: waited for 'Space Manager: slave idle wait' Slave ID=0x0, =0x0, =0x0 wait_id=74 seq_num=75 snap_id=1 wait times: snap=5.004622 sec, exc=5.004622 sec, total=5.004622 sec wait times: max=5.000000 sec wait counts: calls=1 os=1 occurred after 0.000028 sec of elapsed time 6: waited for 'Space Manager: slave idle wait' Slave ID=0x0, =0x0, =0x0 wait_id=73 seq_num=74 snap_id=1 wait times: snap=5.008324 sec, exc=5.008324 sec, total=5.008324 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=72 seq_num=73 snap_id=1 wait times: snap=5.010944 sec, exc=5.010944 sec, total=5.010944 sec wait times: max=5.000000 sec wait counts: calls=1 os=1 occurred after 0.000028 sec of elapsed time 8: 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.012304 sec, exc=5.012304 sec, total=5.012304 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=70 seq_num=71 snap_id=1 wait times: snap=5.014753 sec, exc=5.014753 sec, total=5.014753 sec wait times: max=5.000000 sec wait counts: calls=1 os=1 occurred after 0.000028 sec of elapsed time Sampled Session History of session 177 serial 21209 --------------------------------------------------- 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, 21:59:53 - 22:01:53] idle wait at each sample ------------------------------------------------------------------------------- Process diagnostic dump actual duration=0.000000 sec (max dump time=30.000000 sec) *** 2025-05-10 22:01:53.760 ------------------------------------------------------------------------------- Trace Bucket Dump Begin: default bucket for process 22 (osid: 10024, W000) TIME(*=approx):SEQ:COMPONENT:FILE@LINE:FUNCTION:SECT/DUMP: [EVENT#:PID:SID] DATA ------------------------------------------------------------------------------- 2025-05-10 20:23:35.060276 :955C2662: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-05-10 20:23:35.067864 :955C267E:db_trace:ktc.c@8711:ktcAutoTxnTrace(): [10441:22:177] atxpus:psdpgi.c:2235 2025-05-10 20:23:35.068253 :955C267F: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-05-10 20:23:35.068293 :955C2682:db_trace:ktc.c@8711:ktcAutoTxnTrace(): [10441:22:177] atxpop:psdpgi.c:2235 2025-05-10 20:23:35.069191 :955C2688: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-05-10 20:23:35.069316 :955C2691: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-05-10 20:24:05.198267 :955C3013:db_trace:kst.c@698:kstpsodel(): [10280:22:0] kst: process state object about to be deleted 2025-05-10 20:24:30.454962 :955C37B2:db_trace:kst.c@673:kstipg(): [10280:22:0] kst: process state object created on 05-10 20:24:30.446 2025-05-10 20:24:30.454964 :955C37B3:db_trace:kst.c@679:kstipg(): [10280:22:0] kst: process info: ospid=9440 pso_num=22 pso_serial#=190 2025-05-10 20:24:30.455115 :955C37B4:db_trace:kso.c@4070:ksonfy(): [10420:22:0] kso: new process: pid=9440 (legacy spawn) 2025-05-10 20:24:30.461561 :955C37B5: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-05-10 20:24:30.461769 :955C37BA: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-05-10 20:24:30.462555 :955C37BF:db_trace:kst.c@698:kstpsodel(): [10280:22:0] kst: process state object about to be deleted 2025-05-10 20:24:31.470070 :955C37CE:db_trace:kst.c@673:kstipg(): [10280:22:0] kst: process state object created on 05-10 20:24:31.462 2025-05-10 20:24:31.470072 :955C37CF:db_trace:kst.c@679:kstipg(): [10280:22:0] kst: process info: ospid=12720 pso_num=22 pso_serial#=191 2025-05-10 20:24:31.470208 :955C37D0:db_trace:kso.c@4070:ksonfy(): [10420:22:0] kso: new process: pid=12720 (legacy spawn) 2025-05-10 20:24:31.495751 :955C37D1: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-05-10 20:24:31.495935 :955C37D6: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-05-10 20:24:31.496759 :955C37DB:db_trace:kst.c@698:kstpsodel(): [10280:22:0] kst: process state object about to be deleted 2025-05-10 20:24:34.267240 :955C38C3:db_trace:kst.c@673:kstipg(): [10280:22:0] kst: process state object created on 05-10 20:24:34.253 2025-05-10 20:24:34.267241 :955C38C4:db_trace:kst.c@679:kstipg(): [10280:22:0] kst: process info: ospid=12580 pso_num=22 pso_serial#=192 2025-05-10 20:24:34.267371 :955C38C5:db_trace:kso.c@4070:ksonfy(): [10420:22:0] kso: new process: pid=12580 (legacy spawn) 2025-05-10 20:24:34.273728 :955C38C6: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-05-10 20:24:34.277325 :955C38CB: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-05-10 20:24:34.278279 :955C38D0:db_trace:kst.c@698:kstpsodel(): [10280:22:0] kst: process state object about to be deleted 2025-05-10 20:24:34.286933 :955C38D3:db_trace:kst.c@673:kstipg(): [10280:22:0] kst: process state object created on 05-10 20:24:34.284 2025-05-10 20:24:34.286935 :955C38D4:db_trace:kst.c@679:kstipg(): [10280:22:0] kst: process info: ospid=6556 pso_num=22 pso_serial#=193 2025-05-10 20:24:34.287072 :955C38D5:db_trace:kso.c@4070:ksonfy(): [10420:22:0] kso: new process: pid=6556 (legacy spawn) 2025-05-10 20:24:34.293404 :955C38D6: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-05-10 20:24:34.293578 :955C38DF: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-05-10 20:24:34.294373 :955C38E0:db_trace:kst.c@698:kstpsodel(): [10280:22:0] kst: process state object about to be deleted 2025-05-10 20:24:35.164956 :955C3977:db_trace:kst.c@673:kstipg(): [10280:22:0] kst: process state object created on 05-10 20:24:35.159 2025-05-10 20:24:35.164958 :955C3978:db_trace:kst.c@679:kstipg(): [10280:22:0] kst: process info: ospid=10996 pso_num=22 pso_serial#=194 2025-05-10 20:24:35.165097 :955C3979:db_trace:kso.c@4093:ksonfy(): [10420:22:0] kso: new process: pid=10996 osp_idx=0 osp_ver=178184 osp_pg=0 (spawn #168846) 2025-05-10 20:24:35.165098 :955C397A:db_trace:kso.c@4099:ksonfy(): [10420:22:0] kso: new process: first_req_pid=4308 spawner_pid=3660 sga_crt_ts=x8A8A 2025-05-10 20:24:35.165098 :955C397B:db_trace:kso.c@4103:ksonfy(): [10420:22:0] kso: new process: pso_index=22 reservation=237 time=4179452328 2025-05-10 20:24:35.165098 :955C397C:db_trace:kso.c@4109:ksonfy(): [10420:22:0] kso: spawn diagnostics: queue time=0 secs 2025-05-10 20:24:35.165099 :955C397D:db_trace:kso.c@4111:ksonfy(): [10420:22:0] kso: spawn diagnostics: fork time=0 secs 2025-05-10 20:24:35.165099 :955C397E:db_trace:kso.c@4113:ksonfy(): [10420:22:0] kso: spawn diagnostics: exec time=0 secs 2025-05-10 20:24:35.165099 :955C397F:db_trace:kso.c@4115:ksonfy(): [10420:22:0] kso: spawn diagnostics: pre dbkc time=0 secs 2025-05-10 20:24:35.165099 :955C3980:db_trace:kso.c@4117:ksonfy(): [10420:22:0] kso: spawn diagnostics: post dbkc time=0 secs 2025-05-10 20:24:35.165583 :955C3981:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:22:177] KSL POST SENT postee=59 loc='kso2.h LINE:416 ID:ksoreq_reply' id1=0 id2=0 name= type=0 2025-05-10 20:24:35.166252 :955C3996: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-05-10 20:24:35.180611 :955C39B2:db_trace:ktc.c@8711:ktcAutoTxnTrace(): [10441:22:177] atxpus:psdpgi.c:2235 2025-05-10 20:24:35.180696 :955C39B3:db_trace:ktc.c@8711:ktcAutoTxnTrace(): [10441:22:177] atxpop:psdpgi.c:2235 2025-05-10 20:24:35.181487 :955C39B4:db_trace:ktc.c@8711:ktcAutoTxnTrace(): [10441:22:177] atxpus:psdpgi.c:2235 2025-05-10 20:24:35.181819 :955C39B5: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-05-10 20:24:35.181857 :955C39B8:db_trace:ktc.c@8711:ktcAutoTxnTrace(): [10441:22:177] atxpop:psdpgi.c:2235 2025-05-10 20:24:35.189711 :955C39BE: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-05-10 20:24:35.189776 :955C39C1:db_trace:ktc.c@8711:ktcAutoTxnTrace(): [10441:22:177] atxpus:ktcc.c:879 2025-05-10 20:24:35.189811 :955C39C2:db_trace:ktc.c@8711:ktcAutoTxnTrace(): [10441:22:177] atxpop:ktcc.c:879 2025-05-10 20:24:35.190190 :955C39C8:db_trace:kwqid.c@2146:kwqidrdq(): [10960:22:177] kwqidrdq: Error: 1403 occured in OCI execute 2025-05-10 20:24:35.190545 :955C39C9:db_trace:kwqid.c@2146:kwqidrdq(): [10960:22:177] kwqidrdq: Error: 1403 occured in OCI execute 2025-05-10 20:24:35.190731 :955C39CA:db_trace:ktc.c@8711:ktcAutoTxnTrace(): [10441:22:177] atxpus:psdpgi.c:2235 2025-05-10 20:24:35.190963 :955C39CB: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-05-10 20:24:35.191003 :955C39CE:db_trace:ktc.c@8711:ktcAutoTxnTrace(): [10441:22:177] atxpop:psdpgi.c:2235 2025-05-10 20:24:35.192641 :955C39D4:db_trace:ktc.c@8711:ktcAutoTxnTrace(): [10441:22:177] atxpus:psdpgi.c:2235 2025-05-10 20:24:35.192881 :955C39D5: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-05-10 20:24:35.192911 :955C39D8:db_trace:ktc.c@8711:ktcAutoTxnTrace(): [10441:22:177] atxpop:psdpgi.c:2235 2025-05-10 20:24:35.193800 :955C39DE: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-05-10 20:24:35.193923 :955C39E6: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-05-10 20:25:05.295247 :955C4339:db_trace:kst.c@698:kstpsodel(): [10280:22:0] kst: process state object about to be deleted 2025-05-10 20:25:05.499987 :955C439E:db_trace:kst.c@673:kstipg(): [10280:22:0] kst: process state object created on 05-10 20:25:05.495 2025-05-10 20:25:05.499989 :955C439F:db_trace:kst.c@679:kstipg(): [10280:22:0] kst: process info: ospid=7192 pso_num=22 pso_serial#=195 2025-05-10 20:25:05.500126 :955C43A0:db_trace:kso.c@4093:ksonfy(): [10420:22:0] kso: new process: pid=7192 osp_idx=0 osp_ver=178185 osp_pg=0 (spawn #168848) 2025-05-10 20:25:05.500126 :955C43A1:db_trace:kso.c@4099:ksonfy(): [10420:22:0] kso: new process: first_req_pid=1236 spawner_pid=3660 sga_crt_ts=x8A8A 2025-05-10 20:25:05.500127 :955C43A2:db_trace:kso.c@4103:ksonfy(): [10420:22:0] kso: new process: pso_index=22 reservation=238 time=4179482671 2025-05-10 20:25:05.500127 :955C43A3:db_trace:kso.c@4109:ksonfy(): [10420:22:0] kso: spawn diagnostics: queue time=0 secs 2025-05-10 20:25:05.500127 :955C43A4:db_trace:kso.c@4111:ksonfy(): [10420:22:0] kso: spawn diagnostics: fork time=0 secs 2025-05-10 20:25:05.500128 :955C43A5:db_trace:kso.c@4113:ksonfy(): [10420:22:0] kso: spawn diagnostics: exec time=0 secs 2025-05-10 20:25:05.500128 :955C43A6:db_trace:kso.c@4115:ksonfy(): [10420:22:0] kso: spawn diagnostics: pre dbkc time=0 secs 2025-05-10 20:25:05.500128 :955C43A7:db_trace:kso.c@4117:ksonfy(): [10420:22:0] kso: spawn diagnostics: post dbkc time=0 secs 2025-05-10 20:25:05.500626 :955C43A8: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-05-10 20:25:05.500673 :955C43AF: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-05-10 20:35:06.340568 :955D06EE:db_trace:kst.c@698:kstpsodel(): [10280:22:0] kst: process state object about to be deleted 2025-05-10 20:35:06.845413 :955D077F:db_trace:kst.c@673:kstipg(): [10280:22:0] kst: process state object created on 05-10 20:35:06.841 2025-05-10 20:35:06.845415 :955D0780:db_trace:kst.c@679:kstipg(): [10280:22:0] kst: process info: ospid=9028 pso_num=22 pso_serial#=196 2025-05-10 20:35:06.845553 :955D0781:db_trace:kso.c@4093:ksonfy(): [10420:22:0] kso: new process: pid=9028 osp_idx=0 osp_ver=178186 osp_pg=0 (spawn #168870) 2025-05-10 20:35:06.845553 :955D0782:db_trace:kso.c@4099:ksonfy(): [10420:22:0] kso: new process: first_req_pid=1236 spawner_pid=3660 sga_crt_ts=x8A8A 2025-05-10 20:35:06.845554 :955D0783:db_trace:kso.c@4103:ksonfy(): [10420:22:0] kso: new process: pso_index=22 reservation=239 time=4180084015 2025-05-10 20:35:06.845554 :955D0784:db_trace:kso.c@4109:ksonfy(): [10420:22:0] kso: spawn diagnostics: queue time=0 secs 2025-05-10 20:35:06.845554 :955D0785:db_trace:kso.c@4111:ksonfy(): [10420:22:0] kso: spawn diagnostics: fork time=0 secs 2025-05-10 20:35:06.845555 :955D0786:db_trace:kso.c@4113:ksonfy(): [10420:22:0] kso: spawn diagnostics: exec time=0 secs 2025-05-10 20:35:06.845555 :955D0787:db_trace:kso.c@4115:ksonfy(): [10420:22:0] kso: spawn diagnostics: pre dbkc time=0 secs 2025-05-10 20:35:06.845555 :955D0788:db_trace:kso.c@4117:ksonfy(): [10420:22:0] kso: spawn diagnostics: post dbkc time=0 secs 2025-05-10 20:35:06.846068 :955D0789: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-05-10 20:35:06.846117 :955D0792: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-05-10 20:45:07.728083 :955DCC44:db_trace:kst.c@698:kstpsodel(): [10280:22:0] kst: process state object about to be deleted 2025-05-10 20:45:08.123366 :955DCCB0:db_trace:kst.c@673:kstipg(): [10280:22:0] kst: process state object created on 05-10 20:45:08.118 2025-05-10 20:45:08.123368 :955DCCB1:db_trace:kst.c@679:kstipg(): [10280:22:0] kst: process info: ospid=12548 pso_num=22 pso_serial#=197 2025-05-10 20:45:08.123503 :955DCCB2:db_trace:kso.c@4093:ksonfy(): [10420:22:0] kso: new process: pid=12548 osp_idx=0 osp_ver=178187 osp_pg=0 (spawn #168893) 2025-05-10 20:45:08.123504 :955DCCB3:db_trace:kso.c@4099:ksonfy(): [10420:22:0] kso: new process: first_req_pid=1236 spawner_pid=3660 sga_crt_ts=x8A8A 2025-05-10 20:45:08.123504 :955DCCB4:db_trace:kso.c@4103:ksonfy(): [10420:22:0] kso: new process: pso_index=22 reservation=240 time=4180685296 2025-05-10 20:45:08.123505 :955DCCB5:db_trace:kso.c@4109:ksonfy(): [10420:22:0] kso: spawn diagnostics: queue time=0 secs 2025-05-10 20:45:08.123505 :955DCCB6:db_trace:kso.c@4111:ksonfy(): [10420:22:0] kso: spawn diagnostics: fork time=0 secs 2025-05-10 20:45:08.123505 :955DCCB7:db_trace:kso.c@4113:ksonfy(): [10420:22:0] kso: spawn diagnostics: exec time=0 secs 2025-05-10 20:45:08.123506 :955DCCB8:db_trace:kso.c@4115:ksonfy(): [10420:22:0] kso: spawn diagnostics: pre dbkc time=0 secs 2025-05-10 20:45:08.123506 :955DCCB9:db_trace:kso.c@4117:ksonfy(): [10420:22:0] kso: spawn diagnostics: post dbkc time=0 secs 2025-05-10 20:45:08.123990 :955DCCBA: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-05-10 20:45:08.124035 :955DCCC1: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-05-10 20:55:09.070952 :955E90A4:db_trace:kst.c@698:kstpsodel(): [10280:22:0] kst: process state object about to be deleted 2025-05-10 20:55:09.341297 :955E910E:db_trace:kst.c@673:kstipg(): [10280:22:0] kst: process state object created on 05-10 20:55:09.337 2025-05-10 20:55:09.341299 :955E910F:db_trace:kst.c@679:kstipg(): [10280:22:0] kst: process info: ospid=12644 pso_num=22 pso_serial#=198 2025-05-10 20:55:09.341436 :955E9110:db_trace:kso.c@4093:ksonfy(): [10420:22:0] kso: new process: pid=12644 osp_idx=0 osp_ver=178188 osp_pg=0 (spawn #168916) 2025-05-10 20:55:09.341437 :955E9111:db_trace:kso.c@4099:ksonfy(): [10420:22:0] kso: new process: first_req_pid=1236 spawner_pid=3660 sga_crt_ts=x8A8A 2025-05-10 20:55:09.341437 :955E9112:db_trace:kso.c@4103:ksonfy(): [10420:22:0] kso: new process: pso_index=22 reservation=241 time=4181286515 2025-05-10 20:55:09.341437 :955E9113:db_trace:kso.c@4109:ksonfy(): [10420:22:0] kso: spawn diagnostics: queue time=0 secs 2025-05-10 20:55:09.341438 :955E9114:db_trace:kso.c@4111:ksonfy(): [10420:22:0] kso: spawn diagnostics: fork time=0 secs 2025-05-10 20:55:09.341438 :955E9115:db_trace:kso.c@4113:ksonfy(): [10420:22:0] kso: spawn diagnostics: exec time=0 secs 2025-05-10 20:55:09.341439 :955E9116:db_trace:kso.c@4115:ksonfy(): [10420:22:0] kso: spawn diagnostics: pre dbkc time=0 secs 2025-05-10 20:55:09.341439 :955E9117:db_trace:kso.c@4117:ksonfy(): [10420:22:0] kso: spawn diagnostics: post dbkc time=0 secs 2025-05-10 20:55:09.341947 :955E9118: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-05-10 20:55:09.341991 :955E911F: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-05-10 21:05:10.309932 :955F55BD:db_trace:kst.c@698:kstpsodel(): [10280:22:0] kst: process state object about to be deleted 2025-05-10 21:05:10.549132 :955F565D:db_trace:kst.c@673:kstipg(): [10280:22:0] kst: process state object created on 05-10 21:05:10.544 2025-05-10 21:05:10.549135 :955F565E:db_trace:kst.c@679:kstipg(): [10280:22:0] kst: process info: ospid=10928 pso_num=22 pso_serial#=199 2025-05-10 21:05:10.549273 :955F565F:db_trace:kso.c@4093:ksonfy(): [10420:22:0] kso: new process: pid=10928 osp_idx=0 osp_ver=178189 osp_pg=0 (spawn #168943) 2025-05-10 21:05:10.549274 :955F5660:db_trace:kso.c@4099:ksonfy(): [10420:22:0] kso: new process: first_req_pid=1236 spawner_pid=3660 sga_crt_ts=x8A8A 2025-05-10 21:05:10.549274 :955F5661:db_trace:kso.c@4103:ksonfy(): [10420:22:0] kso: new process: pso_index=22 reservation=242 time=4181887718 2025-05-10 21:05:10.549274 :955F5662:db_trace:kso.c@4109:ksonfy(): [10420:22:0] kso: spawn diagnostics: queue time=0 secs 2025-05-10 21:05:10.549275 :955F5663:db_trace:kso.c@4111:ksonfy(): [10420:22:0] kso: spawn diagnostics: fork time=0 secs 2025-05-10 21:05:10.549275 :955F5664:db_trace:kso.c@4113:ksonfy(): [10420:22:0] kso: spawn diagnostics: exec time=0 secs 2025-05-10 21:05:10.549276 :955F5665:db_trace:kso.c@4115:ksonfy(): [10420:22:0] kso: spawn diagnostics: pre dbkc time=0 secs 2025-05-10 21:05:10.549276 :955F5666:db_trace:kso.c@4117:ksonfy(): [10420:22:0] kso: spawn diagnostics: post dbkc time=0 secs 2025-05-10 21:05:10.549781 :955F5667: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-05-10 21:05:10.549826 :955F566E: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-05-10 21:15:11.502588 :95602340:db_trace:kst.c@698:kstpsodel(): [10280:22:0] kst: process state object about to be deleted 2025-05-10 21:15:11.882332 :956023D2:db_trace:kst.c@673:kstipg(): [10280:22:0] kst: process state object created on 05-10 21:15:11.877 2025-05-10 21:15:11.882334 :956023D3:db_trace:kst.c@679:kstipg(): [10280:22:0] kst: process info: ospid=580 pso_num=22 pso_serial#=200 2025-05-10 21:15:11.882474 :956023D4:db_trace:kso.c@4093:ksonfy(): [10420:22:0] kso: new process: pid=580 osp_idx=0 osp_ver=178190 osp_pg=0 (spawn #168966) 2025-05-10 21:15:11.882474 :956023D5:db_trace:kso.c@4099:ksonfy(): [10420:22:0] kso: new process: first_req_pid=1236 spawner_pid=3660 sga_crt_ts=x8A8A 2025-05-10 21:15:11.882475 :956023D6:db_trace:kso.c@4103:ksonfy(): [10420:22:0] kso: new process: pso_index=22 reservation=243 time=4182489046 2025-05-10 21:15:11.882475 :956023D7:db_trace:kso.c@4109:ksonfy(): [10420:22:0] kso: spawn diagnostics: queue time=0 secs 2025-05-10 21:15:11.882476 :956023D8:db_trace:kso.c@4111:ksonfy(): [10420:22:0] kso: spawn diagnostics: fork time=0 secs 2025-05-10 21:15:11.882476 :956023D9:db_trace:kso.c@4113:ksonfy(): [10420:22:0] kso: spawn diagnostics: exec time=0 secs 2025-05-10 21:15:11.882477 :956023DA:db_trace:kso.c@4115:ksonfy(): [10420:22:0] kso: spawn diagnostics: pre dbkc time=0 secs 2025-05-10 21:15:11.882477 :956023DB:db_trace:kso.c@4117:ksonfy(): [10420:22:0] kso: spawn diagnostics: post dbkc time=0 secs 2025-05-10 21:15:11.882969 :956023DC: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-05-10 21:15:11.883022 :956023E2: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-05-10 21:15:41.918610 :95602DA2:db_trace:ksl2.c@2477:kslwtbctx(): [10005:22:177] KSL WAIT BEG [latch free] 136537728/0x8236680 259/0x103 0/0x0 wait_id=7 seq_num=8 snap_id=1 2025-05-10 21:15:41.918636 :95602DB3:db_trace:ksl2.c@2611:kslwtectx(): [10005:22:177] KSL WAIT END [latch free] 136537728/0x8236680 259/0x103 0/0x0 wait_id=7 seq_num=8 snap_id=1 2025-05-10 21:15:41.918638 :95602DB4:db_trace:ksl2.c@2619:kslwtectx(): [10005:22:177] KSL WAIT END wait times (usecs) - snap=26, exc=26, tot=26 2025-05-10 21:25:12.815433 :9560E6F0:db_trace:kst.c@698:kstpsodel(): [10280:22:0] kst: process state object about to be deleted 2025-05-10 21:25:13.174063 :9560E757:db_trace:kst.c@673:kstipg(): [10280:22:0] kst: process state object created on 05-10 21:25:13.169 2025-05-10 21:25:13.174065 :9560E758:db_trace:kst.c@679:kstipg(): [10280:22:0] kst: process info: ospid=8088 pso_num=22 pso_serial#=201 2025-05-10 21:25:13.174212 :9560E759:db_trace:kso.c@4093:ksonfy(): [10420:22:0] kso: new process: pid=8088 osp_idx=0 osp_ver=178191 osp_pg=0 (spawn #168989) 2025-05-10 21:25:13.174213 :9560E75A:db_trace:kso.c@4099:ksonfy(): [10420:22:0] kso: new process: first_req_pid=1236 spawner_pid=3660 sga_crt_ts=x8A8A 2025-05-10 21:25:13.174214 :9560E75B:db_trace:kso.c@4103:ksonfy(): [10420:22:0] kso: new process: pso_index=22 reservation=244 time=4183090343 2025-05-10 21:25:13.174214 :9560E75C:db_trace:kso.c@4109:ksonfy(): [10420:22:0] kso: spawn diagnostics: queue time=0 secs 2025-05-10 21:25:13.174214 :9560E75D:db_trace:kso.c@4111:ksonfy(): [10420:22:0] kso: spawn diagnostics: fork time=0 secs 2025-05-10 21:25:13.174215 :9560E75E:db_trace:kso.c@4113:ksonfy(): [10420:22:0] kso: spawn diagnostics: exec time=0 secs 2025-05-10 21:25:13.174215 :9560E75F:db_trace:kso.c@4115:ksonfy(): [10420:22:0] kso: spawn diagnostics: pre dbkc time=0 secs 2025-05-10 21:25:13.174215 :9560E760:db_trace:kso.c@4117:ksonfy(): [10420:22:0] kso: spawn diagnostics: post dbkc time=0 secs 2025-05-10 21:25:13.174724 :9560E761: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-05-10 21:25:13.174770 :9560E769: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-05-10 21:35:14.449750 :9561AA54: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-05-10 21:45:15.388933 :95626DF9:db_trace:kst.c@698:kstpsodel(): [10280:22:0] kst: process state object about to be deleted 2025-05-10 21:45:15.737463 :95626E5C:db_trace:kst.c@673:kstipg(): [10280:22:0] kst: process state object created on 05-10 21:45:15.732 2025-05-10 21:45:15.737465 :95626E5D:db_trace:kst.c@679:kstipg(): [10280:22:0] kst: process info: ospid=4640 pso_num=22 pso_serial#=202 2025-05-10 21:45:15.737603 :95626E5E:db_trace:kso.c@4093:ksonfy(): [10420:22:0] kso: new process: pid=4640 osp_idx=0 osp_ver=178192 osp_pg=0 (spawn #169033) 2025-05-10 21:45:15.737603 :95626E5F:db_trace:kso.c@4099:ksonfy(): [10420:22:0] kso: new process: first_req_pid=1236 spawner_pid=3660 sga_crt_ts=x8A8A 2025-05-10 21:45:15.737604 :95626E60:db_trace:kso.c@4103:ksonfy(): [10420:22:0] kso: new process: pso_index=22 reservation=245 time=4184292906 2025-05-10 21:45:15.737604 :95626E61:db_trace:kso.c@4109:ksonfy(): [10420:22:0] kso: spawn diagnostics: queue time=0 secs 2025-05-10 21:45:15.737604 :95626E62:db_trace:kso.c@4111:ksonfy(): [10420:22:0] kso: spawn diagnostics: fork time=0 secs 2025-05-10 21:45:15.737605 :95626E63:db_trace:kso.c@4113:ksonfy(): [10420:22:0] kso: spawn diagnostics: exec time=0 secs 2025-05-10 21:45:15.737605 :95626E64:db_trace:kso.c@4115:ksonfy(): [10420:22:0] kso: spawn diagnostics: pre dbkc time=0 secs 2025-05-10 21:45:15.737605 :95626E65:db_trace:kso.c@4117:ksonfy(): [10420:22:0] kso: spawn diagnostics: post dbkc time=0 secs 2025-05-10 21:45:15.738113 :95626E66: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-05-10 21:45:15.738161 :95626E70: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-05-10 21:55:16.708696 :95633152:db_trace:kst.c@698:kstpsodel(): [10280:22:0] kst: process state object about to be deleted 2025-05-10 21:55:16.979856 :956331B4:db_trace:kst.c@673:kstipg(): [10280:22:0] kst: process state object created on 05-10 21:55:16.974 2025-05-10 21:55:16.979858 :956331B5:db_trace:kst.c@679:kstipg(): [10280:22:0] kst: process info: ospid=10024 pso_num=22 pso_serial#=203 2025-05-10 21:55:16.980011 :956331B6:db_trace:kso.c@4093:ksonfy(): [10420:22:0] kso: new process: pid=10024 osp_idx=0 osp_ver=178193 osp_pg=0 (spawn #169056) 2025-05-10 21:55:16.980012 :956331B7:db_trace:kso.c@4099:ksonfy(): [10420:22:0] kso: new process: first_req_pid=1236 spawner_pid=3660 sga_crt_ts=x8A8A 2025-05-10 21:55:16.980013 :956331B8:db_trace:kso.c@4103:ksonfy(): [10420:22:0] kso: new process: pso_index=22 reservation=246 time=4184894140 2025-05-10 21:55:16.980013 :956331B9:db_trace:kso.c@4109:ksonfy(): [10420:22:0] kso: spawn diagnostics: queue time=0 secs 2025-05-10 21:55:16.980014 :956331BA:db_trace:kso.c@4111:ksonfy(): [10420:22:0] kso: spawn diagnostics: fork time=0 secs 2025-05-10 21:55:16.980014 :956331BB:db_trace:kso.c@4113:ksonfy(): [10420:22:0] kso: spawn diagnostics: exec time=0 secs 2025-05-10 21:55:16.980015 :956331BC:db_trace:kso.c@4115:ksonfy(): [10420:22:0] kso: spawn diagnostics: pre dbkc time=0 secs 2025-05-10 21:55:16.980015 :956331BD:db_trace:kso.c@4117:ksonfy(): [10420:22:0] kso: spawn diagnostics: post dbkc time=0 secs 2025-05-10 21:55:16.980587 :956331BE: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-05-10 21:55:16.980658 :956331C8: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: 10024, W000)