Trace file d:\app\administrator\diag\rdbms\orcl\orcl\trace\cdmp_20250527220006\orcl_j003_13460_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:37265M/63366M, Ph+PgF:44203M/72582M Instance name: orcl Redo thread mounted by this instance: 1 Oracle process number: 29 Windows thread id: 13460, image: ORACLE.EXE (J003) *** 2025-05-27 22:00:07.090 *** SESSION ID:(233.23597) 2025-05-27 22:00:07.090 *** 2025-05-27 22:00:07.090 Process diagnostic dump for ORACLE.EXE (J003), OS id=13460, pid: 29, proc_ser: 39, sid: 233, sess_ser: 23597 ------------------------------------------------------------------------------- current sql: call dbms_stats.gather_database_stats_job_proc ( ) client details: O/S info: user: SYSTEM, term: WIN-3PIMCL4OH3L, ospid: 13460 machine: WIN-3PIMCL4OH3L program: ORACLE.EXE (J003) application name: DBMS_SCHEDULER, hash value=2478762354 action name: ORA$AT_OS_OPT_SY_12501, hash value=2875772746 Current Wait Stack: Not in wait; last wait ended 0.817540 sec ago Wait State: fixed_waits=0 flags=0x21 boundary=0x0000000000000000/-1 Session Wait History: elapsed time of 0.817566 sec since last wait 0: waited for 'Disk file operations I/O' FileOperation=0x5, fileno=0x0, filetype=0x3 wait_id=131 seq_num=132 snap_id=1 wait times: snap=0.000207 sec, exc=0.000207 sec, total=0.000207 sec wait times: max=infinite wait counts: calls=0 os=0 occurred after 0.000005 sec of elapsed time 1: waited for 'log file sequential read' log#=0x27f9, block#=0x0, blocks=0x0 wait_id=130 seq_num=131 snap_id=1 wait times: snap=0.000005 sec, exc=0.000005 sec, total=0.000005 sec wait times: max=infinite wait counts: calls=0 os=0 occurred after 0.005752 sec of elapsed time 2: waited for 'log file sequential read' log#=0x27f9, block#=0x0, blocks=0x0 wait_id=129 seq_num=130 snap_id=1 wait times: snap=0.000020 sec, exc=0.000020 sec, total=0.000020 sec wait times: max=infinite wait counts: calls=0 os=0 occurred after 0.131574 sec of elapsed time 3: waited for 'log file sequential read' log#=0x0, block#=0x6000, blocks=0x800 wait_id=128 seq_num=129 snap_id=1 wait times: snap=0.000310 sec, exc=0.000310 sec, total=0.000310 sec wait times: max=infinite wait counts: calls=0 os=0 occurred after 0.000004 sec of elapsed time 4: waited for 'log file sequential read' log#=0x0, block#=0x5800, blocks=0x800 wait_id=127 seq_num=128 snap_id=1 wait times: snap=0.000305 sec, exc=0.000305 sec, total=0.000305 sec wait times: max=infinite wait counts: calls=0 os=0 occurred after 0.000005 sec of elapsed time 5: waited for 'log file sequential read' log#=0x0, block#=0x5000, blocks=0x800 wait_id=126 seq_num=127 snap_id=1 wait times: snap=0.000288 sec, exc=0.000288 sec, total=0.000288 sec wait times: max=infinite wait counts: calls=0 os=0 occurred after 0.000004 sec of elapsed time 6: waited for 'log file sequential read' log#=0x0, block#=0x4800, blocks=0x800 wait_id=125 seq_num=126 snap_id=1 wait times: snap=0.000299 sec, exc=0.000299 sec, total=0.000299 sec wait times: max=infinite wait counts: calls=0 os=0 occurred after 0.000018 sec of elapsed time 7: waited for 'log file sequential read' log#=0x0, block#=0x4000, blocks=0x800 wait_id=124 seq_num=125 snap_id=1 wait times: snap=0.000314 sec, exc=0.000314 sec, total=0.000314 sec wait times: max=infinite wait counts: calls=0 os=0 occurred after 0.408910 sec of elapsed time 8: waited for 'log file sequential read' log#=0x27f9, block#=0x800, blocks=0x800 wait_id=123 seq_num=124 snap_id=1 wait times: snap=0.000206 sec, exc=0.000206 sec, total=0.000206 sec wait times: max=infinite wait counts: calls=0 os=0 occurred after 0.002632 sec of elapsed time 9: waited for 'log file sequential read' log#=0x27f9, block#=0x0, blocks=0x0 wait_id=122 seq_num=123 snap_id=1 wait times: snap=0.000002 sec, exc=0.000002 sec, total=0.000002 sec wait times: max=infinite wait counts: calls=0 os=0 occurred after 0.000150 sec of elapsed time Sampled Session History of session 233 serial 23597 --------------------------------------------------- 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 --------------------------------------------------- [7 samples, 22:00:00 - 22:00:06] not in wait at each sample [1 sample, 21:59:59] idle wait at each sample [session created at: 22:00:00] ------------------------------------------------------------------------------- Process diagnostic dump actual duration=0.000000 sec (max dump time=30.000000 sec) *** 2025-05-27 22:00:07.090 ------------------------------------------------------------------------------- Trace Bucket Dump Begin: default bucket for process 29 (osid: 13460, J003) TIME(*=approx):SEQ:COMPONENT:FILE@LINE:FUNCTION:SECT/DUMP: [EVENT#:PID:SID] DATA ------------------------------------------------------------------------------- 2025-05-27 09:00:09.482524 :9C9E312F:db_trace:kso.c@4099:ksonfy(): [10420:29:0] kso: new process: first_req_pid=3704 spawner_pid=3660 sga_crt_ts=x8A8A 2025-05-27 09:00:09.482524 :9C9E3130:db_trace:kso.c@4103:ksonfy(): [10420:29:0] kso: new process: pso_index=29 reservation=90 time=1312181719 2025-05-27 09:00:09.482525 :9C9E3131:db_trace:kso.c@4109:ksonfy(): [10420:29:0] kso: spawn diagnostics: queue time=0 secs 2025-05-27 09:00:09.482525 :9C9E3132:db_trace:kso.c@4111:ksonfy(): [10420:29:0] kso: spawn diagnostics: fork time=0 secs 2025-05-27 09:00:09.482526 :9C9E3133:db_trace:kso.c@4113:ksonfy(): [10420:29:0] kso: spawn diagnostics: exec time=0 secs 2025-05-27 09:00:09.482526 :9C9E3134:db_trace:kso.c@4115:ksonfy(): [10420:29:0] kso: spawn diagnostics: pre dbkc time=0 secs 2025-05-27 09:00:09.482526 :9C9E3135:db_trace:kso.c@4117:ksonfy(): [10420:29:0] kso: spawn diagnostics: post dbkc time=0 secs 2025-05-27 09:00:09.483007 :9C9E3136:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=18 loc='kso2.h LINE:416 ID:ksoreq_reply' id1=0 id2=0 name= type=0 2025-05-27 09:00:09.483046 :9C9E313C:db_trace:ksl2.c@12699:ksliwat(): [10005:29:233] 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-27 09:00:09.490845 :9C9E315D:db_trace:kst.c@698:kstpsodel(): [10280:29:0] kst: process state object about to be deleted 2025-05-27 10:00:17.233233 :9CA2CDDB:db_trace:kst.c@673:kstipg(): [10280:29:0] kst: process state object created on 05-27 10:00:17.231 2025-05-27 10:00:17.233234 :9CA2CDDC:db_trace:kst.c@679:kstipg(): [10280:29:0] kst: process info: ospid=12956 pso_num=29 pso_serial#=32 2025-05-27 10:00:17.233368 :9CA2CDDD:db_trace:kso.c@4093:ksonfy(): [10420:29:0] kso: new process: pid=12956 osp_idx=27 osp_ver=11761 osp_pg=0 (spawn #224156) 2025-05-27 10:00:17.233369 :9CA2CDDE:db_trace:kso.c@4099:ksonfy(): [10420:29:0] kso: new process: first_req_pid=3704 spawner_pid=3660 sga_crt_ts=x8A8A 2025-05-27 10:00:17.233370 :9CA2CDDF:db_trace:kso.c@4103:ksonfy(): [10420:29:0] kso: new process: pso_index=29 reservation=91 time=1315789469 2025-05-27 10:00:17.233370 :9CA2CDE0:db_trace:kso.c@4109:ksonfy(): [10420:29:0] kso: spawn diagnostics: queue time=0 secs 2025-05-27 10:00:17.233370 :9CA2CDE1:db_trace:kso.c@4111:ksonfy(): [10420:29:0] kso: spawn diagnostics: fork time=0 secs 2025-05-27 10:00:17.233371 :9CA2CDE2:db_trace:kso.c@4113:ksonfy(): [10420:29:0] kso: spawn diagnostics: exec time=0 secs 2025-05-27 10:00:17.233371 :9CA2CDE3:db_trace:kso.c@4115:ksonfy(): [10420:29:0] kso: spawn diagnostics: pre dbkc time=0 secs 2025-05-27 10:00:17.233371 :9CA2CDE4:db_trace:kso.c@4117:ksonfy(): [10420:29:0] kso: spawn diagnostics: post dbkc time=0 secs 2025-05-27 10:00:17.233939 :9CA2CDE5:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=18 loc='kso2.h LINE:416 ID:ksoreq_reply' id1=0 id2=0 name= type=0 2025-05-27 10:00:17.233990 :9CA2CDEB:db_trace:ksl2.c@12699:ksliwat(): [10005:29:233] 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-27 10:00:17.242184 :9CA2CE0D:db_trace:kst.c@698:kstpsodel(): [10280:29:0] kst: process state object about to be deleted 2025-05-27 11:00:25.171946 :9CA76A6B:db_trace:kst.c@673:kstipg(): [10280:29:0] kst: process state object created on 05-27 11:00:25.169 2025-05-27 11:00:25.171948 :9CA76A6C:db_trace:kst.c@679:kstipg(): [10280:29:0] kst: process info: ospid=13792 pso_num=29 pso_serial#=33 2025-05-27 11:00:25.172090 :9CA76A6D:db_trace:kso.c@4093:ksonfy(): [10420:29:0] kso: new process: pid=13792 osp_idx=27 osp_ver=11762 osp_pg=0 (spawn #224295) 2025-05-27 11:00:25.172091 :9CA76A6E:db_trace:kso.c@4099:ksonfy(): [10420:29:0] kso: new process: first_req_pid=3704 spawner_pid=3660 sga_crt_ts=x8A8A 2025-05-27 11:00:25.172092 :9CA76A6F:db_trace:kso.c@4103:ksonfy(): [10420:29:0] kso: new process: pso_index=29 reservation=92 time=1319397407 2025-05-27 11:00:25.172092 :9CA76A70:db_trace:kso.c@4109:ksonfy(): [10420:29:0] kso: spawn diagnostics: queue time=0 secs 2025-05-27 11:00:25.172092 :9CA76A71:db_trace:kso.c@4111:ksonfy(): [10420:29:0] kso: spawn diagnostics: fork time=0 secs 2025-05-27 11:00:25.172093 :9CA76A72:db_trace:kso.c@4113:ksonfy(): [10420:29:0] kso: spawn diagnostics: exec time=0 secs 2025-05-27 11:00:25.172093 :9CA76A73:db_trace:kso.c@4115:ksonfy(): [10420:29:0] kso: spawn diagnostics: pre dbkc time=0 secs 2025-05-27 11:00:25.172094 :9CA76A74:db_trace:kso.c@4117:ksonfy(): [10420:29:0] kso: spawn diagnostics: post dbkc time=0 secs 2025-05-27 11:00:25.172626 :9CA76A75:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=18 loc='kso2.h LINE:416 ID:ksoreq_reply' id1=0 id2=0 name= type=0 2025-05-27 11:00:25.172676 :9CA76A7B:db_trace:ksl2.c@12699:ksliwat(): [10005:29:233] 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-27 11:00:25.181285 :9CA76A8D:db_trace:kst.c@698:kstpsodel(): [10280:29:0] kst: process state object about to be deleted 2025-05-27 12:00:33.994507 :9CAC026B:db_trace:kst.c@673:kstipg(): [10280:29:0] kst: process state object created on 05-27 12:00:33.991 2025-05-27 12:00:33.994508 :9CAC026C:db_trace:kst.c@679:kstipg(): [10280:29:0] kst: process info: ospid=15288 pso_num=29 pso_serial#=34 2025-05-27 12:00:33.994648 :9CAC026D:db_trace:kso.c@4093:ksonfy(): [10420:29:0] kso: new process: pid=15288 osp_idx=27 osp_ver=11763 osp_pg=0 (spawn #224433) 2025-05-27 12:00:33.994649 :9CAC026E:db_trace:kso.c@4099:ksonfy(): [10420:29:0] kso: new process: first_req_pid=3704 spawner_pid=3660 sga_crt_ts=x8A8A 2025-05-27 12:00:33.994649 :9CAC026F:db_trace:kso.c@4103:ksonfy(): [10420:29:0] kso: new process: pso_index=29 reservation=93 time=1323006235 2025-05-27 12:00:33.994650 :9CAC0270:db_trace:kso.c@4109:ksonfy(): [10420:29:0] kso: spawn diagnostics: queue time=0 secs 2025-05-27 12:00:33.994650 :9CAC0271:db_trace:kso.c@4111:ksonfy(): [10420:29:0] kso: spawn diagnostics: fork time=0 secs 2025-05-27 12:00:33.994651 :9CAC0272:db_trace:kso.c@4113:ksonfy(): [10420:29:0] kso: spawn diagnostics: exec time=0 secs 2025-05-27 12:00:33.994651 :9CAC0273:db_trace:kso.c@4115:ksonfy(): [10420:29:0] kso: spawn diagnostics: pre dbkc time=0 secs 2025-05-27 12:00:33.994652 :9CAC0274:db_trace:kso.c@4117:ksonfy(): [10420:29:0] kso: spawn diagnostics: post dbkc time=0 secs 2025-05-27 12:00:33.995243 :9CAC0275:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=18 loc='kso2.h LINE:416 ID:ksoreq_reply' id1=0 id2=0 name= type=0 2025-05-27 12:00:33.995291 :9CAC027B:db_trace:ksl2.c@12699:ksliwat(): [10005:29:233] 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-27 12:00:34.003604 :9CAC028D:db_trace:kst.c@698:kstpsodel(): [10280:29:0] kst: process state object about to be deleted 2025-05-27 13:00:42.028584 :9CB09B89:db_trace:kst.c@673:kstipg(): [10280:29:0] kst: process state object created on 05-27 13:00:42.026 2025-05-27 13:00:42.028585 :9CB09B8A:db_trace:kst.c@679:kstipg(): [10280:29:0] kst: process info: ospid=14972 pso_num=29 pso_serial#=35 2025-05-27 13:00:42.028728 :9CB09B8B:db_trace:kso.c@4093:ksonfy(): [10420:29:0] kso: new process: pid=14972 osp_idx=27 osp_ver=11764 osp_pg=0 (spawn #224572) 2025-05-27 13:00:42.028729 :9CB09B8C:db_trace:kso.c@4099:ksonfy(): [10420:29:0] kso: new process: first_req_pid=3704 spawner_pid=3660 sga_crt_ts=x8A8A 2025-05-27 13:00:42.028730 :9CB09B8D:db_trace:kso.c@4103:ksonfy(): [10420:29:0] kso: new process: pso_index=29 reservation=94 time=1326614266 2025-05-27 13:00:42.028730 :9CB09B8E:db_trace:kso.c@4109:ksonfy(): [10420:29:0] kso: spawn diagnostics: queue time=0 secs 2025-05-27 13:00:42.028731 :9CB09B8F:db_trace:kso.c@4111:ksonfy(): [10420:29:0] kso: spawn diagnostics: fork time=0 secs 2025-05-27 13:00:42.028731 :9CB09B90:db_trace:kso.c@4113:ksonfy(): [10420:29:0] kso: spawn diagnostics: exec time=0 secs 2025-05-27 13:00:42.028731 :9CB09B91:db_trace:kso.c@4115:ksonfy(): [10420:29:0] kso: spawn diagnostics: pre dbkc time=0 secs 2025-05-27 13:00:42.028732 :9CB09B92:db_trace:kso.c@4117:ksonfy(): [10420:29:0] kso: spawn diagnostics: post dbkc time=0 secs 2025-05-27 13:00:42.029309 :9CB09B93:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=18 loc='kso2.h LINE:416 ID:ksoreq_reply' id1=0 id2=0 name= type=0 2025-05-27 13:00:42.029369 :9CB09B99:db_trace:ksl2.c@12699:ksliwat(): [10005:29:233] 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-27 13:00:42.037471 :9CB09BAB:db_trace:kst.c@698:kstpsodel(): [10280:29:0] kst: process state object about to be deleted 2025-05-27 14:00:49.843090 :9CB53498:db_trace:kst.c@673:kstipg(): [10280:29:0] kst: process state object created on 05-27 14:00:49.841 2025-05-27 14:00:49.843091 :9CB53499:db_trace:kst.c@679:kstipg(): [10280:29:0] kst: process info: ospid=11776 pso_num=29 pso_serial#=36 2025-05-27 14:00:49.843226 :9CB5349A:db_trace:kso.c@4093:ksonfy(): [10420:29:0] kso: new process: pid=11776 osp_idx=27 osp_ver=11765 osp_pg=0 (spawn #224710) 2025-05-27 14:00:49.843227 :9CB5349B:db_trace:kso.c@4099:ksonfy(): [10420:29:0] kso: new process: first_req_pid=3704 spawner_pid=3660 sga_crt_ts=x8A8A 2025-05-27 14:00:49.843228 :9CB5349C:db_trace:kso.c@4103:ksonfy(): [10420:29:0] kso: new process: pso_index=29 reservation=95 time=1330222079 2025-05-27 14:00:49.843228 :9CB5349D:db_trace:kso.c@4109:ksonfy(): [10420:29:0] kso: spawn diagnostics: queue time=0 secs 2025-05-27 14:00:49.843229 :9CB5349E:db_trace:kso.c@4111:ksonfy(): [10420:29:0] kso: spawn diagnostics: fork time=0 secs 2025-05-27 14:00:49.843229 :9CB5349F:db_trace:kso.c@4113:ksonfy(): [10420:29:0] kso: spawn diagnostics: exec time=0 secs 2025-05-27 14:00:49.843230 :9CB534A0:db_trace:kso.c@4115:ksonfy(): [10420:29:0] kso: spawn diagnostics: pre dbkc time=0 secs 2025-05-27 14:00:49.843230 :9CB534A1:db_trace:kso.c@4117:ksonfy(): [10420:29:0] kso: spawn diagnostics: post dbkc time=0 secs 2025-05-27 14:00:49.843784 :9CB534A2:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=18 loc='kso2.h LINE:416 ID:ksoreq_reply' id1=0 id2=0 name= type=0 2025-05-27 14:00:49.843841 :9CB534A8:db_trace:ksl2.c@12699:ksliwat(): [10005:29:233] 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-27 14:00:49.852088 :9CB534BA:db_trace:kst.c@698:kstpsodel(): [10280:29:0] kst: process state object about to be deleted 2025-05-27 15:00:57.733591 :9CB9CB1F:db_trace:kst.c@673:kstipg(): [10280:29:0] kst: process state object created on 05-27 15:00:57.731 2025-05-27 15:00:57.733593 :9CB9CB20:db_trace:kst.c@679:kstipg(): [10280:29:0] kst: process info: ospid=14708 pso_num=29 pso_serial#=37 2025-05-27 15:00:57.733743 :9CB9CB21:db_trace:kso.c@4093:ksonfy(): [10420:29:0] kso: new process: pid=14708 osp_idx=27 osp_ver=11766 osp_pg=0 (spawn #224849) 2025-05-27 15:00:57.733744 :9CB9CB22:db_trace:kso.c@4099:ksonfy(): [10420:29:0] kso: new process: first_req_pid=3704 spawner_pid=3660 sga_crt_ts=x8A8A 2025-05-27 15:00:57.733744 :9CB9CB23:db_trace:kso.c@4103:ksonfy(): [10420:29:0] kso: new process: pso_index=29 reservation=96 time=1333829969 2025-05-27 15:00:57.733744 :9CB9CB24:db_trace:kso.c@4109:ksonfy(): [10420:29:0] kso: spawn diagnostics: queue time=0 secs 2025-05-27 15:00:57.733745 :9CB9CB25:db_trace:kso.c@4111:ksonfy(): [10420:29:0] kso: spawn diagnostics: fork time=0 secs 2025-05-27 15:00:57.733745 :9CB9CB26:db_trace:kso.c@4113:ksonfy(): [10420:29:0] kso: spawn diagnostics: exec time=0 secs 2025-05-27 15:00:57.733746 :9CB9CB27:db_trace:kso.c@4115:ksonfy(): [10420:29:0] kso: spawn diagnostics: pre dbkc time=0 secs 2025-05-27 15:00:57.733746 :9CB9CB28:db_trace:kso.c@4117:ksonfy(): [10420:29:0] kso: spawn diagnostics: post dbkc time=0 secs 2025-05-27 15:00:57.734261 :9CB9CB29:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=18 loc='kso2.h LINE:416 ID:ksoreq_reply' id1=0 id2=0 name= type=0 2025-05-27 15:00:57.734309 :9CB9CB2F:db_trace:ksl2.c@12699:ksliwat(): [10005:29:233] 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-27 15:00:57.742539 :9CB9CB41:db_trace:kst.c@698:kstpsodel(): [10280:29:0] kst: process state object about to be deleted 2025-05-27 16:00:07.625295 :9CBE4EAA:db_trace:kst.c@673:kstipg(): [10280:29:0] kst: process state object created on 05-27 16:00:07.614 2025-05-27 16:00:07.625297 :9CBE4EAB:db_trace:kst.c@679:kstipg(): [10280:29:0] kst: process info: ospid=13572 pso_num=29 pso_serial#=38 2025-05-27 16:00:07.625436 :9CBE4EAC:db_trace:kso.c@4093:ksonfy(): [10420:29:0] kso: new process: pid=13572 osp_idx=27 osp_ver=11767 osp_pg=0 (spawn #224985) 2025-05-27 16:00:07.625437 :9CBE4EAD:db_trace:kso.c@4099:ksonfy(): [10420:29:0] kso: new process: first_req_pid=3704 spawner_pid=3660 sga_crt_ts=x8A8A 2025-05-27 16:00:07.625437 :9CBE4EAE:db_trace:kso.c@4103:ksonfy(): [10420:29:0] kso: new process: pso_index=29 reservation=97 time=1337379875 2025-05-27 16:00:07.625437 :9CBE4EAF:db_trace:kso.c@4109:ksonfy(): [10420:29:0] kso: spawn diagnostics: queue time=0 secs 2025-05-27 16:00:07.625438 :9CBE4EB0:db_trace:kso.c@4111:ksonfy(): [10420:29:0] kso: spawn diagnostics: fork time=0 secs 2025-05-27 16:00:07.625438 :9CBE4EB1:db_trace:kso.c@4113:ksonfy(): [10420:29:0] kso: spawn diagnostics: exec time=0 secs 2025-05-27 16:00:07.625438 :9CBE4EB2:db_trace:kso.c@4115:ksonfy(): [10420:29:0] kso: spawn diagnostics: pre dbkc time=0 secs 2025-05-27 16:00:07.625438 :9CBE4EB3:db_trace:kso.c@4117:ksonfy(): [10420:29:0] kso: spawn diagnostics: post dbkc time=0 secs 2025-05-27 16:00:07.625940 :9CBE4EB4:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=18 loc='kso2.h LINE:416 ID:ksoreq_reply' id1=0 id2=0 name= type=0 2025-05-27 16:00:07.625983 :9CBE4EBA:db_trace:ksl2.c@12699:ksliwat(): [10005:29:233] 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-27 16:00:07.633126 :9CBE4EC8:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-27 16:00:07.634188 :9CBE4ED0:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-27 16:00:07.634733 :9CBE4ED8:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-27 16:00:07.635180 :9CBE4EE0:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-27 16:00:07.635607 :9CBE4EE8:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-27 16:00:07.638124 :9CBE4EF0:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-27 16:00:07.639227 :9CBE4EF8:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-27 16:00:07.687206 :9CBE4F00:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-27 16:00:07.688354 :9CBE4F08:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-27 16:00:07.689223 :9CBE4F10:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-27 16:00:07.689463 :9CBE4F18:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-27 16:00:07.689746 :9CBE4F20:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-27 16:00:07.691534 :9CBE4F28:db_trace:kst.c@698:kstpsodel(): [10280:29:0] kst: process state object about to be deleted 2025-05-27 22:00:00.583194 :9CD9BF32:db_trace:kst.c@673:kstipg(): [10280:29:0] kst: process state object created on 05-27 22:00:00.572 2025-05-27 22:00:00.583196 :9CD9BF33:db_trace:kst.c@679:kstipg(): [10280:29:0] kst: process info: ospid=13460 pso_num=29 pso_serial#=39 2025-05-27 22:00:00.583335 :9CD9BF38:db_trace:kso.c@4093:ksonfy(): [10420:29:0] kso: new process: pid=13460 osp_idx=27 osp_ver=11768 osp_pg=0 (spawn #225818) 2025-05-27 22:00:00.583335 :9CD9BF39:db_trace:kso.c@4099:ksonfy(): [10420:29:0] kso: new process: first_req_pid=4308 spawner_pid=3660 sga_crt_ts=x8A8A 2025-05-27 22:00:00.583336 :9CD9BF3A:db_trace:kso.c@4103:ksonfy(): [10420:29:0] kso: new process: pso_index=29 reservation=98 time=1358972829 2025-05-27 22:00:00.583336 :9CD9BF3B:db_trace:kso.c@4109:ksonfy(): [10420:29:0] kso: spawn diagnostics: queue time=0 secs 2025-05-27 22:00:00.583337 :9CD9BF3C:db_trace:kso.c@4111:ksonfy(): [10420:29:0] kso: spawn diagnostics: fork time=0 secs 2025-05-27 22:00:00.583337 :9CD9BF3D:db_trace:kso.c@4113:ksonfy(): [10420:29:0] kso: spawn diagnostics: exec time=0 secs 2025-05-27 22:00:00.583337 :9CD9BF3E:db_trace:kso.c@4115:ksonfy(): [10420:29:0] kso: spawn diagnostics: pre dbkc time=0 secs 2025-05-27 22:00:00.583338 :9CD9BF3F:db_trace:kso.c@4117:ksonfy(): [10420:29:0] kso: spawn diagnostics: post dbkc time=0 secs 2025-05-27 22:00:00.583906 :9CD9BF45:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=59 loc='kso2.h LINE:416 ID:ksoreq_reply' id1=0 id2=0 name= type=0 2025-05-27 22:00:00.588840 :9CD9BF5C:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-27 22:00:00.588876 :9CD9BF5F:db_trace:ktc.c@8711:ktcAutoTxnTrace(): [10441:29:233] atxpus:jslv.c:9203 2025-05-27 22:00:00.605930 :9CD9C12F:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-27 22:00:00.606136 :9CD9C140:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-27 22:00:00.606320 :9CD9C154:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-27 22:00:00.606480 :9CD9C15C:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-27 22:00:00.606664 :9CD9C164:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-27 22:00:00.606828 :9CD9C16C:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-27 22:00:00.606992 :9CD9C174:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-27 22:00:00.607146 :9CD9C17C:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-27 22:00:00.607297 :9CD9C184:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-27 22:00:00.607446 :9CD9C18C:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-27 22:00:00.607605 :9CD9C194:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-27 22:00:00.607752 :9CD9C19C:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-27 22:00:00.607900 :9CD9C1A4:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-27 22:00:00.608062 :9CD9C1AC:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-27 22:00:00.608227 :9CD9C1B4:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-27 22:00:00.608376 :9CD9C1BC:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-27 22:00:00.608544 :9CD9C1C4:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-27 22:00:00.608895 :9CD9C1CC:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-27 22:00:00.609067 :9CD9C1D4:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-27 22:00:00.609217 :9CD9C1DC:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-27 22:00:00.609483 :9CD9C1E4:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-27 22:00:00.609719 :9CD9C1EC:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-27 22:00:00.610019 :9CD9C1F4:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-27 22:00:00.610720 :9CD9C1FC:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-27 22:00:00.610951 :9CD9C204:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-27 22:00:00.637145 :9CD9C20C:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-27 22:00:02.212944*:9CD9C4AE:sql_mon_query:keswx.c@6099:keswxCurPushMonitoring(begin): xsc=0x0000000030183AD0 estart=1748354402 eid=18844508 ctx=0x0000000777968158 cwh=0x0000000029990AB8 cpu=0 buffg=2 interb=0 r=0 rb=0 w=0 wb=0 2025-05-27 22:00:02.212944*:9CD9C4B2:sql_mon_query:keswx.c@2839:keswxCurPrepare(): Allocate monitor context: xsc=0x0000000030183AD0 curCtx=0x000000003F7EC4B8 pubTabIdxCnt=0 2025-05-27 22:00:02.212944*:9CD9C4B3:sql_mon_query:keswx.c@6131:keswxCurPushMonitoring(): clear monitoring flag for xsc=0x0000000030183AD0 2025-05-27 22:00:02.212944*:9CD9C4B4:sql_mon_query:keswx.c@6263:keswxCurPushMonitoring(end): full monitoring not yet started for xsc=0x0000000030183AD0 2025-05-27 22:00:02.212944*:9CD9C4B5:sql_mon_query:keswx.c@6099:keswxCurPushMonitoring(begin): xsc=0x00000000301BAAF8 estart=1748354400 eid=16777352 ctx=0x000000077B54EAC8 cwh=0x0000000029990608 cpu=1375000 buffg=75608 interb=196608 r=24 rb=196608 w=0 wb=0 2025-05-27 22:00:02.212944*:9CD9C4B6:sql_mon_query:keswx.c@2839:keswxCurPrepare(): Allocate monitor context: xsc=0x00000000301BAAF8 curCtx=0x000000003F601240 pubTabIdxCnt=0 2025-05-27 22:00:02.212944*:9CD9C4B7:sql_mon_query:keswx.c@6131:keswxCurPushMonitoring(): clear monitoring flag for xsc=0x00000000301BAAF8 2025-05-27 22:00:02.212944*:9CD9C4B8:sql_mon_query:keswx.c@6263:keswxCurPushMonitoring(end): full monitoring not yet started for xsc=0x00000000301BAAF8 2025-05-27 22:00:02.212944*:9CD9C4B9:sql_mon_query:keswx.c@3282:keswxCurEndPlanMonitoringCb(begin): xsc=0x0000000030183AD0 curCtx=0x000000003F7EC4B8 xsc->flg4=65792 flags=1 2025-05-27 22:00:02.212944*:9CD9C4BA:sql_mon_query:keswx.c@3389:keswxCurEndPlanMonitoringCb(end): monitoring has ended for xsc=0x0000000030183AD0 2025-05-27 22:00:02.291066*:9CD9C4F3:sql_mon_query:keswx.c@3282:keswxCurEndPlanMonitoringCb(begin): xsc=0x00000000301BAAF8 curCtx=0x000000003F601240 xsc->flg4=65792 flags=2 2025-05-27 22:00:02.291066*:9CD9C4F4:sql_mon_query:keswx.c@3389:keswxCurEndPlanMonitoringCb(end): monitoring has ended for xsc=0x00000000301BAAF8 2025-05-27 22:00:02.294221 :9CD9C4F5:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-27 22:00:02.313963 :9CD9C505:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-27 22:00:02.315892 :9CD9C50D:db_trace:ktc.c@8711:ktcAutoTxnTrace(): [10441:29:233] atxpus:psdpgi.c:2235 2025-05-27 22:00:02.316091 :9CD9C50E:db_trace:ktc.c@8711:ktcAutoTxnTrace(): [10441:29:233] atxpop:psdpgi.c:2235 2025-05-27 22:00:02.317191 :9CD9C517:db_trace:ktu.c@4871:ktuaex1r(): [10442:29:233] Extension usn 9, ext 1, nex 3 2025-05-27 22:00:02.317203 :9CD9C518:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=30 loc='ksq.h LINE:1877 ID:ksqrcl' id1=0 id2=0 name= type=0 2025-05-27 22:00:02.317212 :9CD9C51A:db_trace:ktusm.c@2117:ktusmasp(): [10445:29:233] des1:tsn:1 rdba:0x008c12f1 where: ktspbwh1: ktspfsrch 2025-05-27 22:00:02.317366 :9CD9C51F:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-27 22:00:02.318296 :9CD9C539:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-27 22:00:02.319634 :9CD9C54E:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-27 22:00:02.320004 :9CD9C556:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-27 22:00:02.369193*:SQL_Analyze:qksan.c@3402:qksanAnalyzeSql(begin): qksanAnalyzeSql(enter): goal=15 options=16778048 pgadep=0 binds#=0 byPos=0 timeLim=0 timeFired=0 2025-05-27 22:00:02.384822*:SQL_Analyze:qksan.c@936:qksanBindSql(begin): binding for SQL analyze 2025-05-27 22:00:02.384822*:SQL_Analyze:qksan.c@1344:qksanBindSql(end): Done binding: status=0 ret=0 bind#=0 byPos=1 wasBoundP=0x0000000000000000 bindIndP=0x0000000000000000 2025-05-27 22:00:02.384822*:SQL_Analyze:qksan.c@6338:qksanAvgExecStats(): The number of total executions: 1 and execution count: 0 2025-05-27 22:00:02.384822*:SQL_Analyze:qksan.c@4776:qksanPostAnalyzeDump(begin): qksanPostAnalyzeDump(): Dumping analyze context after compilation qksanStatus=SUCCESS ecode=0 2025-05-27 22:00:02.384822*:SQL_Analyze:qksan.c@4800:qksanPostAnalyzeDump(end): 2025-05-27 22:00:02.384822*:SQL_Analyze:qksan.c@3690:qksanAnalyzeSql(end): exit: ecode=0 status=0 2025-05-27 22:00:02.450295 :9CD9C601:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-27 22:00:04.325847 :9CD9C7EE:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-27 22:00:04.325858 :9CD9C7EF:db_trace:ktur.c@3079:ktuabt(): [10444:29:233] ABORT TRANSACTION - xid: 0x0001.009.0000c102 2025-05-27 22:00:06.731356 :9CD9C94D:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-27 22:00:06.732754 :9CD9C955:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-27 22:00:06.742861 :9CD9C95D:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 2025-05-27 22:00:06.766757 :9CD9C971:db_trace:ksl2.c@14083:ksl_update_post_stats(): [10005:29:233] KSL POST SENT postee=14 loc='ksa2.h LINE:282 ID:ksasnd' id1=0 id2=0 name= type=0 ------------------------------------------------------------------------------- Trace Bucket Dump End: default bucket for process 29 (osid: 13460, J003)