Trace file d:\app\administrator\diag\rdbms\orcl\orcl\trace\cdmp_20250513220006\orcl_j002_9064_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:37408M/63366M, Ph+PgF:44705M/72582M Instance name: orcl Redo thread mounted by this instance: 1 Oracle process number: 28 Windows thread id: 9064, image: ORACLE.EXE (J002) *** 2025-05-13 22:00:06.721 *** SESSION ID:(225.25743) 2025-05-13 22:00:06.721 *** 2025-05-13 22:00:06.721 Process diagnostic dump for ORACLE.EXE (J002), OS id=9064, pid: 28, proc_ser: 124, sid: 225, sess_ser: 25743 ------------------------------------------------------------------------------- current sql: client details: O/S info: user: SYSTEM, term: WIN-3PIMCL4OH3L, ospid: 9064 machine: WIN-3PIMCL4OH3L program: ORACLE.EXE (J002) Current Wait Stack: 0: waiting for 'jobq slave wait' =0x0, =0x0, =0x0 wait_id=10 seq_num=11 snap_id=1 wait times: snap=0.209684 sec, exc=0.209684 sec, total=0.209684 sec wait times: max=0.500000 sec, heur=4.553656 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.000007 sec since current wait 0: waited for 'jobq slave wait' =0x0, =0x0, =0x0 wait_id=9 seq_num=10 snap_id=1 wait times: snap=0.499992 sec, exc=0.499992 sec, total=0.499992 sec wait times: max=0.500000 sec wait counts: calls=1 os=1 occurred after 0.000011 sec of elapsed time 1: waited for 'jobq slave wait' =0x0, =0x0, =0x0 wait_id=8 seq_num=9 snap_id=1 wait times: snap=0.500174 sec, exc=0.500174 sec, total=0.500174 sec wait times: max=0.500000 sec wait counts: calls=1 os=1 occurred after 0.000007 sec of elapsed time 2: waited for 'jobq slave wait' =0x0, =0x0, =0x0 wait_id=7 seq_num=8 snap_id=1 wait times: snap=0.511694 sec, exc=0.511694 sec, total=0.511694 sec wait times: max=0.500000 sec wait counts: calls=1 os=1 occurred after 0.000009 sec of elapsed time 3: waited for 'jobq slave wait' =0x0, =0x0, =0x0 wait_id=6 seq_num=7 snap_id=1 wait times: snap=0.499998 sec, exc=0.499998 sec, total=0.499998 sec wait times: max=0.500000 sec wait counts: calls=1 os=1 occurred after 0.000009 sec of elapsed time 4: waited for 'jobq slave wait' =0x0, =0x0, =0x0 wait_id=5 seq_num=6 snap_id=1 wait times: snap=0.499550 sec, exc=0.499550 sec, total=0.499550 sec wait times: max=0.500000 sec wait counts: calls=1 os=1 occurred after 0.000005 sec of elapsed time 5: waited for 'jobq slave wait' =0x0, =0x0, =0x0 wait_id=4 seq_num=5 snap_id=1 wait times: snap=0.235127 sec, exc=0.235127 sec, total=0.235127 sec wait times: max=0.500000 sec wait counts: calls=1 os=1 occurred after 0.000010 sec of elapsed time 6: waited for 'jobq slave wait' =0x0, =0x0, =0x0 wait_id=3 seq_num=4 snap_id=1 wait times: snap=0.499991 sec, exc=0.499991 sec, total=0.499991 sec wait times: max=0.500000 sec wait counts: calls=1 os=1 occurred after 0.000006 sec of elapsed time 7: waited for 'jobq slave wait' =0x0, =0x0, =0x0 wait_id=2 seq_num=3 snap_id=1 wait times: snap=0.500005 sec, exc=0.500005 sec, total=0.500005 sec wait times: max=0.500000 sec wait counts: calls=1 os=1 occurred after 0.000007 sec of elapsed time 8: waited for 'jobq slave wait' =0x0, =0x0, =0x0 wait_id=1 seq_num=2 snap_id=1 wait times: snap=0.499240 sec, exc=0.499240 sec, total=0.499240 sec wait times: max=0.500000 sec wait counts: calls=1 os=1 occurred after 0.000005 sec of elapsed time 9: waited for 'jobq slave wait' =0x0, =0x0, =0x0 wait_id=0 seq_num=1 snap_id=1 wait times: snap=0.098125 sec, exc=0.098125 sec, total=0.098125 sec wait times: max=0.500000 sec wait counts: calls=1 os=1 occurred after 0.000000 sec of elapsed time Sampled Session History of session 225 serial 25743 --------------------------------------------------- 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 --------------------------------------------------- [5 samples, 22:00:02 - 22:00:06] idle wait at each sample [session created at: 22:00:02] ------------------------------------------------------------------------------- Process diagnostic dump actual duration=0.000000 sec (max dump time=30.000000 sec) *** 2025-05-13 22:00:06.721 ------------------------------------------------------------------------------- Trace Bucket Dump Begin: default bucket for process 28 (osid: 9064, J002) TIME(*=approx):SEQ:COMPONENT:FILE@LINE:FUNCTION:SECT/DUMP: [EVENT#:PID:SID] DATA ------------------------------------------------------------------------------- 2025-05-13 09:33:48.810030 :967806DA:db_trace:kst.c@698:kstpsodel(): [10280:28:0] kst: process state object about to be deleted 2025-05-13 13:00:18.275625 :9687E442:db_trace:kst.c@673:kstipg(): [10280:28:0] kst: process state object created on 05-13 13:00:18.262 2025-05-13 13:00:18.275627 :9687E443:db_trace:kst.c@679:kstipg(): [10280:28:0] kst: process info: ospid=13104 pso_num=28 pso_serial#=114 2025-05-13 13:00:18.275765 :9687E444:db_trace:kso.c@4093:ksonfy(): [10420:28:0] kso: new process: pid=13104 osp_idx=26 osp_ver=111038 osp_pg=0 (spawn #177907) 2025-05-13 13:00:18.275765 :9687E445:db_trace:kso.c@4099:ksonfy(): [10420:28:0] kso: new process: first_req_pid=3704 spawner_pid=3660 sga_crt_ts=x8A8A 2025-05-13 13:00:18.275766 :9687E446:db_trace:kso.c@4103:ksonfy(): [10420:28:0] kso: new process: pso_index=28 reservation=33 time=117028141 2025-05-13 13:00:18.275766 :9687E447:db_trace:kso.c@4109:ksonfy(): [10420:28:0] kso: spawn diagnostics: queue time=0 secs 2025-05-13 13:00:18.275766 :9687E448:db_trace:kso.c@4111:ksonfy(): [10420:28:0] kso: spawn diagnostics: fork time=0 secs 2025-05-13 13:00:18.275767 :9687E449:db_trace:kso.c@4113:ksonfy(): [10420:28:0] kso: spawn diagnostics: exec time=0 secs 2025-05-13 13:00:18.275768 :9687E44A:db_trace:kso.c@4115:ksonfy(): [10420:28:0] kso: spawn diagnostics: pre dbkc time=0 secs 2025-05-13 13:00:18.275768 :9687E44B:db_trace:kso.c@4117:ksonfy(): [10420:28:0] kso: spawn diagnostics: post dbkc time=0 secs 2025-05-13 13:00:18.276272 :9687E44C:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:28:225] KSL POST SENT postee=18 loc='kso2.h LINE:416 ID:ksoreq_reply' id1=0 id2=0 name= type=0 2025-05-13 13:00:18.276320 :9687E452:db_trace:ksl2.c@12699:ksliwat(): [10005:28:225] KSL POST RCVD poster=18 loc='ksv2.h LINE:1639 ID:ksvpst: run' id1=0 id2=0 name= type=0 fac#=0 facpost=1 2025-05-13 13:00:18.278908 :9687E460:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:28:225] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-13 13:00:18.284346 :9687E468:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:28:225] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-13 13:00:18.285462 :9687E470:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:28:225] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-13 13:00:18.286022 :9687E478:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:28:225] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-13 13:00:18.286515 :9687E480:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:28:225] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-13 13:00:18.286991 :9687E488:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:28:225] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-13 13:00:18.289687 :9687E490:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:28:225] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-13 13:00:18.290834 :9687E498:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:28:225] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-13 13:00:18.339211 :9687E4AB:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:28:225] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-13 13:00:18.340221 :9687E4B3:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:28:225] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-13 13:00:18.340474 :9687E4BB:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:28:225] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-13 13:00:18.340744 :9687E4C3:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:28:225] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-13 13:00:18.342477 :9687E4CB:db_trace:kst.c@698:kstpsodel(): [10280:28:0] kst: process state object about to be deleted 2025-05-13 16:00:03.153445 :9695AC26:db_trace:kst.c@673:kstipg(): [10280:28:0] kst: process state object created on 05-13 16:00:03.142 2025-05-13 16:00:03.153447 :9695AC27:db_trace:kst.c@679:kstipg(): [10280:28:0] kst: process info: ospid=11780 pso_num=28 pso_serial#=115 2025-05-13 16:00:03.153583 :9695AC28:db_trace:kso.c@4070:ksonfy(): [10420:28:0] kso: new process: pid=11780 (legacy spawn) 2025-05-13 16:00:03.160256 :9695AC29:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:28:225] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-13 16:00:03.160430 :9695AC2E:db_trace:ksl2.c@12699:ksliwat(): [10005:28:225] 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-13 16:00:03.161254 :9695AC33:db_trace:kst.c@698:kstpsodel(): [10280:28:0] kst: process state object about to be deleted 2025-05-13 16:00:14.331867 :9695AF9B:db_trace:kst.c@673:kstipg(): [10280:28:0] kst: process state object created on 05-13 16:00:14.328 2025-05-13 16:00:14.331869 :9695AF9C:db_trace:kst.c@679:kstipg(): [10280:28:0] kst: process info: ospid=11236 pso_num=28 pso_serial#=116 2025-05-13 16:00:14.332006 :9695AF9D:db_trace:kso.c@4070:ksonfy(): [10420:28:0] kso: new process: pid=11236 (legacy spawn) 2025-05-13 16:00:14.338402 :9695AF9E:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:28:225] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-13 16:00:14.338572 :9695AFA3:db_trace:ksl2.c@12699:ksliwat(): [10005:28:225] 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-13 16:00:14.345033 :9695AFA8:db_trace:kst.c@698:kstpsodel(): [10280:28:0] kst: process state object about to be deleted 2025-05-13 16:00:14.353903 :9695AFAB:db_trace:kst.c@673:kstipg(): [10280:28:0] kst: process state object created on 05-13 16:00:14.344 2025-05-13 16:00:14.353905 :9695AFAC:db_trace:kst.c@679:kstipg(): [10280:28:0] kst: process info: ospid=12612 pso_num=28 pso_serial#=117 2025-05-13 16:00:14.354049 :9695AFAD:db_trace:kso.c@4070:ksonfy(): [10420:28:0] kso: new process: pid=12612 (legacy spawn) 2025-05-13 16:00:14.360676 :9695AFAE:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:28:225] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-13 16:00:14.360862 :9695AFB7:db_trace:ksl2.c@12699:ksliwat(): [10005:28:225] 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-13 16:00:14.361751 :9695AFB8:db_trace:kst.c@698:kstpsodel(): [10280:28:0] kst: process state object about to be deleted 2025-05-13 16:00:16.935716 :9695B0A0:db_trace:kst.c@673:kstipg(): [10280:28:0] kst: process state object created on 05-13 16:00:16.927 2025-05-13 16:00:16.935718 :9695B0A1:db_trace:kst.c@679:kstipg(): [10280:28:0] kst: process info: ospid=12028 pso_num=28 pso_serial#=118 2025-05-13 16:00:16.935854 :9695B0A2:db_trace:kso.c@4070:ksonfy(): [10420:28:0] kso: new process: pid=12028 (legacy spawn) 2025-05-13 16:00:16.942343 :9695B0A3:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:28:225] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-13 16:00:16.942512 :9695B0A8:db_trace:ksl2.c@12699:ksliwat(): [10005:28:225] 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-13 16:00:16.943381 :9695B0AD:db_trace:kst.c@698:kstpsodel(): [10280:28:0] kst: process state object about to be deleted 2025-05-13 16:00:17.424840 :9695B0B0:db_trace:kst.c@673:kstipg(): [10280:28:0] kst: process state object created on 05-13 16:00:17.411 2025-05-13 16:00:17.424842 :9695B0B1:db_trace:kst.c@679:kstipg(): [10280:28:0] kst: process info: ospid=12928 pso_num=28 pso_serial#=119 2025-05-13 16:00:17.424982 :9695B0B2:db_trace:kso.c@4070:ksonfy(): [10420:28:0] kso: new process: pid=12928 (legacy spawn) 2025-05-13 16:00:17.431464 :9695B0B3:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:28:225] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-13 16:00:17.431629 :9695B0BC:db_trace:ksl2.c@12699:ksliwat(): [10005:28:225] 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-13 16:00:17.432408 :9695B0BD:db_trace:kst.c@698:kstpsodel(): [10280:28:0] kst: process state object about to be deleted 2025-05-13 16:00:17.451843 :9695B0C0:db_trace:kst.c@673:kstipg(): [10280:28:0] kst: process state object created on 05-13 16:00:17.443 2025-05-13 16:00:17.451845 :9695B0C1:db_trace:kst.c@679:kstipg(): [10280:28:0] kst: process info: ospid=12320 pso_num=28 pso_serial#=120 2025-05-13 16:00:17.451983 :9695B0C2:db_trace:kso.c@4070:ksonfy(): [10420:28:0] kso: new process: pid=12320 (legacy spawn) 2025-05-13 16:00:17.458384 :9695B0C3:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:28:225] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-13 16:00:17.458592 :9695B0CC:db_trace:ksl2.c@12699:ksliwat(): [10005:28:225] 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-13 16:00:17.459658 :9695B0CD:db_trace:kst.c@698:kstpsodel(): [10280:28:0] kst: process state object about to be deleted 2025-05-13 20:05:15.542503 :96A86EC4:db_trace:kst.c@673:kstipg(): [10280:28:0] kst: process state object created on 05-13 20:05:15.530 2025-05-13 20:05:15.542505 :96A86EC5:db_trace:kst.c@679:kstipg(): [10280:28:0] kst: process info: ospid=12356 pso_num=28 pso_serial#=121 2025-05-13 20:05:15.542638 :96A86EC6:db_trace:kso.c@4093:ksonfy(): [10420:28:0] kso: new process: pid=12356 osp_idx=26 osp_ver=111045 osp_pg=0 (spawn #178892) 2025-05-13 20:05:15.542639 :96A86EC7:db_trace:kso.c@4099:ksonfy(): [10420:28:0] kso: new process: first_req_pid=3704 spawner_pid=3660 sga_crt_ts=x8A8A 2025-05-13 20:05:15.542639 :96A86EC8:db_trace:kso.c@4103:ksonfy(): [10420:28:0] kso: new process: pso_index=28 reservation=34 time=142525407 2025-05-13 20:05:15.542640 :96A86EC9:db_trace:kso.c@4109:ksonfy(): [10420:28:0] kso: spawn diagnostics: queue time=0 secs 2025-05-13 20:05:15.542640 :96A86ECA:db_trace:kso.c@4111:ksonfy(): [10420:28:0] kso: spawn diagnostics: fork time=0 secs 2025-05-13 20:05:15.542641 :96A86ECB:db_trace:kso.c@4113:ksonfy(): [10420:28:0] kso: spawn diagnostics: exec time=0 secs 2025-05-13 20:05:15.542641 :96A86ECC:db_trace:kso.c@4115:ksonfy(): [10420:28:0] kso: spawn diagnostics: pre dbkc time=0 secs 2025-05-13 20:05:15.542641 :96A86ECD:db_trace:kso.c@4117:ksonfy(): [10420:28:0] kso: spawn diagnostics: post dbkc time=0 secs 2025-05-13 20:05:15.543155 :96A86ECE:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:28:225] KSL POST SENT postee=18 loc='kso2.h LINE:416 ID:ksoreq_reply' id1=0 id2=0 name= type=0 2025-05-13 20:05:15.543193 :96A86ED4:db_trace:ksl2.c@12699:ksliwat(): [10005:28:225] KSL POST RCVD poster=18 loc='ksv2.h LINE:1639 ID:ksvpst: run' id1=0 id2=0 name= type=0 fac#=0 facpost=1 2025-05-13 20:05:15.547250 :96A86EED:db_trace:ktc.c@8711:ktcAutoTxnTrace(): [10441:28:225] atxpus:kelt.c:517 2025-05-13 20:05:15.547295 :96A86EEE:db_trace:ktc.c@8711:ktcAutoTxnTrace(): [10441:28:225] atxpop:kelt.c:517 2025-05-13 20:05:15.547543 :96A86EEF:db_trace:ktc.c@8711:ktcAutoTxnTrace(): [10441:28:225] atxpus:kelt.c:517 2025-05-13 20:05:15.547558 :96A86EF0:db_trace:ktc.c@8711:ktcAutoTxnTrace(): [10441:28:225] atxpop:kelt.c:517 2025-05-13 20:05:15.547763 :96A86EF1:db_trace:ktc.c@8711:ktcAutoTxnTrace(): [10441:28:225] atxpus:kelt.c:517 2025-05-13 20:05:15.547776 :96A86EF2:db_trace:ktc.c@8711:ktcAutoTxnTrace(): [10441:28:225] atxpop:kelt.c:517 2025-05-13 20:05:15.547981 :96A86EF3:db_trace:ktc.c@8711:ktcAutoTxnTrace(): [10441:28:225] atxpus:kelt.c:517 2025-05-13 20:05:15.547994 :96A86EF4:db_trace:ktc.c@8711:ktcAutoTxnTrace(): [10441:28:225] atxpop:kelt.c:517 2025-05-13 20:05:15.548198 :96A86EF5:db_trace:ktc.c@8711:ktcAutoTxnTrace(): [10441:28:225] atxpus:kelt.c:517 2025-05-13 20:05:15.548210 :96A86EF6:db_trace:ktc.c@8711:ktcAutoTxnTrace(): [10441:28:225] atxpop:kelt.c:517 2025-05-13 20:05:15.548410 :96A86EF7:db_trace:ktc.c@8711:ktcAutoTxnTrace(): [10441:28:225] atxpus:kelt.c:517 2025-05-13 20:05:15.548422 :96A86EF8:db_trace:ktc.c@8711:ktcAutoTxnTrace(): [10441:28:225] atxpop:kelt.c:517 2025-05-13 20:05:15.550841 :96A86EF9:db_trace:kst.c@698:kstpsodel(): [10280:28:0] kst: process state object about to be deleted 2025-05-13 21:00:24.631875 :96ACA705:db_trace:kst.c@673:kstipg(): [10280:28:0] kst: process state object created on 05-13 21:00:24.628 2025-05-13 21:00:24.631877 :96ACA706:db_trace:kst.c@679:kstipg(): [10280:28:0] kst: process info: ospid=12976 pso_num=28 pso_serial#=122 2025-05-13 21:00:24.632003 :96ACA707:db_trace:kso.c@4093:ksonfy(): [10420:28:0] kso: new process: pid=12976 osp_idx=26 osp_ver=111046 osp_pg=0 (spawn #179018) 2025-05-13 21:00:24.632004 :96ACA708:db_trace:kso.c@4099:ksonfy(): [10420:28:0] kso: new process: first_req_pid=3704 spawner_pid=3660 sga_crt_ts=x8A8A 2025-05-13 21:00:24.632005 :96ACA709:db_trace:kso.c@4103:ksonfy(): [10420:28:0] kso: new process: pso_index=28 reservation=35 time=145834485 2025-05-13 21:00:24.632005 :96ACA70A:db_trace:kso.c@4109:ksonfy(): [10420:28:0] kso: spawn diagnostics: queue time=0 secs 2025-05-13 21:00:24.632007 :96ACA70B:db_trace:kso.c@4111:ksonfy(): [10420:28:0] kso: spawn diagnostics: fork time=0 secs 2025-05-13 21:00:24.632007 :96ACA70C:db_trace:kso.c@4113:ksonfy(): [10420:28:0] kso: spawn diagnostics: exec time=0 secs 2025-05-13 21:00:24.632008 :96ACA70D:db_trace:kso.c@4115:ksonfy(): [10420:28:0] kso: spawn diagnostics: pre dbkc time=0 secs 2025-05-13 21:00:24.632008 :96ACA70E:db_trace:kso.c@4117:ksonfy(): [10420:28:0] kso: spawn diagnostics: post dbkc time=0 secs 2025-05-13 21:00:24.632493 :96ACA70F:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:28:225] KSL POST SENT postee=18 loc='kso2.h LINE:416 ID:ksoreq_reply' id1=0 id2=0 name= type=0 2025-05-13 21:00:24.632538 :96ACA715:db_trace:ksl2.c@12699:ksliwat(): [10005:28:225] KSL POST RCVD poster=18 loc='ksv2.h LINE:1639 ID:ksvpst: run' id1=0 id2=0 name= type=0 fac#=0 facpost=1 2025-05-13 21:00:24.640033 :96ACA723:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:28:225] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-13 21:00:24.641110 :96ACA72B:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:28:225] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-13 21:00:24.641597 :96ACA733:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:28:225] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-13 21:00:24.642033 :96ACA73B:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:28:225] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-13 21:00:24.642454 :96ACA743:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:28:225] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-13 21:00:24.644940 :96ACA74B:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:28:225] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-13 21:00:24.646020 :96ACA753:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:28:225] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-13 21:00:24.694345 :96ACA75B:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:28:225] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-13 21:00:24.695281 :96ACA763:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:28:225] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-13 21:00:24.695527 :96ACA76B:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:28:225] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-13 21:00:24.695761 :96ACA773:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:28:225] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-13 21:00:24.697512 :96ACA77B:db_trace:kst.c@698:kstpsodel(): [10280:28:0] kst: process state object about to be deleted 2025-05-13 21:35:28.459555 :96AF59C8:db_trace:kst.c@673:kstipg(): [10280:28:0] kst: process state object created on 05-13 21:35:28.447 2025-05-13 21:35:28.459557 :96AF59C9:db_trace:kst.c@679:kstipg(): [10280:28:0] kst: process info: ospid=12480 pso_num=28 pso_serial#=123 2025-05-13 21:35:28.459697 :96AF59CA:db_trace:kso.c@4093:ksonfy(): [10420:28:0] kso: new process: pid=12480 osp_idx=26 osp_ver=111047 osp_pg=0 (spawn #179099) 2025-05-13 21:35:28.459697 :96AF59CB:db_trace:kso.c@4099:ksonfy(): [10420:28:0] kso: new process: first_req_pid=3704 spawner_pid=3660 sga_crt_ts=x8A8A 2025-05-13 21:35:28.459697 :96AF59CC:db_trace:kso.c@4103:ksonfy(): [10420:28:0] kso: new process: pso_index=28 reservation=36 time=147938329 2025-05-13 21:35:28.459698 :96AF59CD:db_trace:kso.c@4109:ksonfy(): [10420:28:0] kso: spawn diagnostics: queue time=0 secs 2025-05-13 21:35:28.459698 :96AF59CE:db_trace:kso.c@4111:ksonfy(): [10420:28:0] kso: spawn diagnostics: fork time=0 secs 2025-05-13 21:35:28.459698 :96AF59CF:db_trace:kso.c@4113:ksonfy(): [10420:28:0] kso: spawn diagnostics: exec time=0 secs 2025-05-13 21:35:28.459699 :96AF59D0:db_trace:kso.c@4115:ksonfy(): [10420:28:0] kso: spawn diagnostics: pre dbkc time=0 secs 2025-05-13 21:35:28.459699 :96AF59D1:db_trace:kso.c@4117:ksonfy(): [10420:28:0] kso: spawn diagnostics: post dbkc time=0 secs 2025-05-13 21:35:28.460220 :96AF59D2:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:28:225] KSL POST SENT postee=18 loc='kso2.h LINE:416 ID:ksoreq_reply' id1=0 id2=0 name= type=0 2025-05-13 21:35:28.460262 :96AF59D8:db_trace:ksl2.c@12699:ksliwat(): [10005:28:225] KSL POST RCVD poster=18 loc='ksv2.h LINE:1639 ID:ksvpst: run' id1=0 id2=0 name= type=0 fac#=0 facpost=1 2025-05-13 21:35:28.464219 :96AF59F1:db_trace:ktc.c@8711:ktcAutoTxnTrace(): [10441:28:225] atxpus:kelt.c:517 2025-05-13 21:35:28.464266 :96AF59F2:db_trace:ktc.c@8711:ktcAutoTxnTrace(): [10441:28:225] atxpop:kelt.c:517 2025-05-13 21:35:28.464509 :96AF59F3:db_trace:ktc.c@8711:ktcAutoTxnTrace(): [10441:28:225] atxpus:kelt.c:517 2025-05-13 21:35:28.464524 :96AF59F4:db_trace:ktc.c@8711:ktcAutoTxnTrace(): [10441:28:225] atxpop:kelt.c:517 2025-05-13 21:35:28.464733 :96AF59F5:db_trace:ktc.c@8711:ktcAutoTxnTrace(): [10441:28:225] atxpus:kelt.c:517 2025-05-13 21:35:28.464746 :96AF59F6:db_trace:ktc.c@8711:ktcAutoTxnTrace(): [10441:28:225] atxpop:kelt.c:517 2025-05-13 21:35:28.464946 :96AF59F7:db_trace:ktc.c@8711:ktcAutoTxnTrace(): [10441:28:225] atxpus:kelt.c:517 2025-05-13 21:35:28.464959 :96AF59F8:db_trace:ktc.c@8711:ktcAutoTxnTrace(): [10441:28:225] atxpop:kelt.c:517 2025-05-13 21:35:28.465163 :96AF59F9:db_trace:ktc.c@8711:ktcAutoTxnTrace(): [10441:28:225] atxpus:kelt.c:517 2025-05-13 21:35:28.465176 :96AF59FA:db_trace:ktc.c@8711:ktcAutoTxnTrace(): [10441:28:225] atxpop:kelt.c:517 2025-05-13 21:35:28.465379 :96AF59FB:db_trace:ktc.c@8711:ktcAutoTxnTrace(): [10441:28:225] atxpus:kelt.c:517 2025-05-13 21:35:28.465391 :96AF59FC:db_trace:ktc.c@8711:ktcAutoTxnTrace(): [10441:28:225] atxpop:kelt.c:517 2025-05-13 21:35:28.467780 :96AF59FD:db_trace:kst.c@698:kstpsodel(): [10280:28:0] kst: process state object about to be deleted 2025-05-13 22:00:02.148092 :96B1366C:db_trace:kst.c@673:kstipg(): [10280:28:0] kst: process state object created on 05-13 22:00:02.147 2025-05-13 22:00:02.148094 :96B1366D:db_trace:kst.c@679:kstipg(): [10280:28:0] kst: process info: ospid=9064 pso_num=28 pso_serial#=124 2025-05-13 22:00:02.148224 :96B1366E:db_trace:kso.c@4093:ksonfy(): [10420:28:0] kso: new process: pid=9064 osp_idx=26 osp_ver=111048 osp_pg=0 (spawn #179156) 2025-05-13 22:00:02.148225 :96B1366F:db_trace:kso.c@4099:ksonfy(): [10420:28:0] kso: new process: first_req_pid=4308 spawner_pid=3660 sga_crt_ts=x8A8A 2025-05-13 22:00:02.148225 :96B13670:db_trace:kso.c@4103:ksonfy(): [10420:28:0] kso: new process: pso_index=28 reservation=37 time=149412000 2025-05-13 22:00:02.148225 :96B13671:db_trace:kso.c@4109:ksonfy(): [10420:28:0] kso: spawn diagnostics: queue time=0 secs 2025-05-13 22:00:02.148226 :96B13672:db_trace:kso.c@4111:ksonfy(): [10420:28:0] kso: spawn diagnostics: fork time=0 secs 2025-05-13 22:00:02.148226 :96B13673:db_trace:kso.c@4113:ksonfy(): [10420:28:0] kso: spawn diagnostics: exec time=0 secs 2025-05-13 22:00:02.148227 :96B13674:db_trace:kso.c@4115:ksonfy(): [10420:28:0] kso: spawn diagnostics: pre dbkc time=0 secs 2025-05-13 22:00:02.148227 :96B13675:db_trace:kso.c@4117:ksonfy(): [10420:28:0] kso: spawn diagnostics: post dbkc time=0 secs 2025-05-13 22:00:02.148694 :96B1367F:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:28:225] KSL POST SENT postee=59 loc='kso2.h LINE:416 ID:ksoreq_reply' id1=0 id2=0 name= type=0 2025-05-13 22:00:02.153627 :96B1369C:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:28:225] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-13 22:00:02.153668 :96B1369F:db_trace:ktc.c@8711:ktcAutoTxnTrace(): [10441:28:225] atxpus:jslv.c:9203 2025-05-13 22:00:02.158335 :96B136CC:KFNU:kfn.c@2200:kfnPrepareASM(): kfnPrepareASM force=0 state_kfnsg=0x7 2025-05-13 22:00:02.158920 :96B136CD:db_trace:kcc.c@13684:kccwbp(): [10021:28:225:1] 0115000000000000 0115000000000000 04c8110000000000 2025-05-13 22:00:02.160657 :96B136FE:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:28:225] KSL POST SENT postee=15 loc='ksr2.h LINE:603 ID:ksrpublish' id1=0 id2=0 name= type=0 2025-05-13 22:00:02.160715 :96B1370E:db_trace:ksl2.c@12699:ksliwat(): [10005:28:225] KSL POST RCVD poster=15 loc='ksr2.h LINE:607 ID:ksrmdone' id1=0 id2=0 name= type=0 fac#=0 facpost=1 2025-05-13 22:00:02.160724 :96B13715:db_trace:ksb.c@6610:ksbcic_int(): [10254:28:225] KSBCIC: (USER) starting cic on opcode KSBCIRCO [1] with args (1 8397264 1) 2025-05-13 22:00:02.160730 :96B13716:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:28:225] KSL POST SENT postee=15 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-13 22:00:02.160756 :96B13722:db_trace:ksl2.c@12699:ksliwat(): [10005:28:225] KSL POST RCVD poster=15 loc='ksa2.h LINE:286 ID:ksasnr' id1=0 id2=0 name= type=0 fac#=0 facpost=1 2025-05-13 22:00:02.161412 :96B13733:db_trace:ksb.c@6610:ksbcic_int(): [10254:28:225] KSBCIC: (USER) starting cic on opcode KSBCICKP [2] with args (4 0 225211073) 2025-05-13 22:00:02.161415 :96B13734:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:28:225] KSL POST SENT postee=15 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-13 22:00:02.161439 :96B1373F:db_trace:ksl2.c@12699:ksliwat(): [10005:28:225] KSL POST RCVD poster=15 loc='ksa2.h LINE:286 ID:ksasnr' id1=0 id2=0 name= type=0 fac#=0 facpost=1 2025-05-13 22:00:02.161448 :96B1374C:db_trace:ksb.c@6610:ksbcic_int(): [10254:28:225] KSBCIC: (USER) starting cic on opcode KSBCICKP [2] with args (6 65564 1) 2025-05-13 22:00:02.161451 :96B1374D:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:28:225] KSL POST SENT postee=15 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-13 22:00:02.161477 :96B1375A:db_trace:ksl2.c@12699:ksliwat(): [10005:28:225] KSL POST RCVD poster=15 loc='ksa2.h LINE:286 ID:ksasnr' id1=0 id2=0 name= type=0 fac#=0 facpost=1 2025-05-13 22:00:02.161479 :96B13763:db_trace:ksb.c@6610:ksbcic_int(): [10254:28:225] KSBCIC: (USER) starting cic on opcode KSBCICKP [2] with args (1 2 65564) 2025-05-13 22:00:02.161482 :96B13766:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:28:225] KSL POST SENT postee=15 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-13 22:00:02.161531 :96B13785:db_trace:ksl2.c@12699:ksliwat(): [10005:28:225] KSL POST RCVD poster=15 loc='ksa2.h LINE:286 ID:ksasnr' id1=0 id2=0 name= type=0 fac#=0 facpost=1 2025-05-13 22:00:02.162465 :96B13818:db_trace:ksl2.c@12699:ksliwat(): [10005:28:225] KSL POST RCVD poster=15 loc='ksq.h LINE:1877 ID:ksqrcl' id1=0 id2=0 name= type=0 fac#=0 facpost=1 2025-05-13 22:00:02.162486 :96B13819:KFNU:kfn.c@2200:kfnPrepareASM(): kfnPrepareASM force=0 state_kfnsg=0x7 2025-05-13 22:00:02.163324 :96B13820:db_trace:kcc.c@13684:kccwbp(): [10021:28:225:1] 0115000000000000 0115000000000000 05c8110000000000 2025-05-13 22:00:02.163681 :96B13821:db_trace:ksb.c@6610:ksbcic_int(): [10254:28:225] KSBCIC: (USER) starting cic on opcode KSBCIBBS [20] with args (2 0 225211073) 2025-05-13 22:00:02.163687 :96B13822:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:28:225] KSL POST SENT postee=15 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-13 22:00:02.163716 :96B1382B:db_trace:ksl2.c@12699:ksliwat(): [10005:28:225] KSL POST RCVD poster=15 loc='ksa2.h LINE:286 ID:ksasnr' id1=0 id2=0 name= type=0 fac#=0 facpost=1 2025-05-13 22:00:02.172117 :96B1388F:db_trace:ktc.c@8711:ktcAutoTxnTrace(): [10441:28:225] atxpop:jslv.c:9203 2025-05-13 22:00:02.173838 :96B13890:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:28:225] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-13 22:00:02.173900 :96B13893:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:28:225] KSL POST SENT postee=59 loc='kkj.h LINE:928 ID:jslve_execute' id1=0 id2=0 name= type=0 2025-05-13 22:00:02.174014 :96B138A0:db_trace:ksl2.c@12699:ksliwat(): [10005:28:225] 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-13 22:00:02.272816 :96B139A8:db_trace:ksl2.c@12699:ksliwat(): [10005:28:225] KSL POST RCVD poster=59 loc='kkj.h LINE:914 ID:kkjpstnp' id1=0 id2=0 name= type=0 fac#=0 facpost=1 2025-05-13 22:00:04.007206 :96B13CF0:db_trace:ksl2.c@12699:ksliwat(): [10005:28:225] KSL POST RCVD poster=59 loc='kkj.h LINE:914 ID:kkjpstnp' id1=0 id2=0 name= type=0 fac#=0 facpost=1 ------------------------------------------------------------------------------- Trace Bucket Dump End: default bucket for process 28 (osid: 9064, J002)