Trace file d:\app\administrator\diag\rdbms\orcl\orcl\trace\cdmp_20250626220009\orcl_j003_580_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:36296M/63366M, Ph+PgF:42426M/72582M Instance name: orcl Redo thread mounted by this instance: 1 Oracle process number: 29 Windows thread id: 580, image: ORACLE.EXE (J003) *** 2025-06-26 22:00:09.199 *** SESSION ID:(233.26991) 2025-06-26 22:00:09.199 *** 2025-06-26 22:00:09.199 Process diagnostic dump for ORACLE.EXE (J003), OS id=580, pid: 29, proc_ser: 194, sid: 233, sess_ser: 26991 ------------------------------------------------------------------------------- current sql: call dbms_stats.gather_database_stats_job_proc ( ) client details: O/S info: user: SYSTEM, term: WIN-3PIMCL4OH3L, ospid: 580 machine: WIN-3PIMCL4OH3L program: ORACLE.EXE (J003) application name: DBMS_SCHEDULER, hash value=2478762354 action name: ORA$AT_OS_OPT_SY_12655, hash value=74802595 Current Wait Stack: Not in wait; last wait ended 1.437965 sec ago Wait State: fixed_waits=0 flags=0x21 boundary=0x0000000000000000/-1 Session Wait History: elapsed time of 1.437991 sec since last wait 0: waited for 'Disk file operations I/O' FileOperation=0x5, fileno=0x0, filetype=0x3 wait_id=143 seq_num=144 snap_id=1 wait times: snap=0.000208 sec, exc=0.000208 sec, total=0.000208 sec wait times: max=infinite wait counts: calls=0 os=0 occurred after 0.000001 sec of elapsed time 1: waited for 'log file sequential read' log#=0x28a9, block#=0x0, blocks=0x0 wait_id=142 seq_num=143 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.000383 sec of elapsed time 2: waited for 'log file sequential read' log#=0x28a9, block#=0x0, blocks=0x0 wait_id=141 seq_num=142 snap_id=1 wait times: snap=0.000022 sec, exc=0.000022 sec, total=0.000022 sec wait times: max=infinite wait counts: calls=0 os=0 occurred after 0.270916 sec of elapsed time 3: waited for 'log file sequential read' log#=0x0, block#=0x6000, blocks=0x800 wait_id=140 seq_num=141 snap_id=1 wait times: snap=0.000356 sec, exc=0.000356 sec, total=0.000356 sec wait times: max=infinite wait counts: calls=0 os=0 occurred after 0.000005 sec of elapsed time 4: waited for 'log file sequential read' log#=0x0, block#=0x5800, blocks=0x800 wait_id=139 seq_num=140 snap_id=1 wait times: snap=0.000306 sec, exc=0.000306 sec, total=0.000306 sec wait times: max=infinite wait counts: calls=0 os=0 occurred after 0.000004 sec of elapsed time 5: waited for 'log file sequential read' log#=0x0, block#=0x5000, blocks=0x800 wait_id=138 seq_num=139 snap_id=1 wait times: snap=0.000303 sec, exc=0.000303 sec, total=0.000303 sec wait times: max=infinite wait counts: calls=0 os=0 occurred after 0.000024 sec of elapsed time 6: waited for 'log file sequential read' log#=0x0, block#=0x4800, blocks=0x800 wait_id=137 seq_num=138 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.000130 sec of elapsed time 7: waited for 'log file sequential read' log#=0x0, block#=0x4000, blocks=0x800 wait_id=136 seq_num=137 snap_id=1 wait times: snap=0.000301 sec, exc=0.000301 sec, total=0.000301 sec wait times: max=infinite wait counts: calls=0 os=0 occurred after 0.274429 sec of elapsed time 8: waited for 'log file sequential read' log#=0x28a9, block#=0x800, blocks=0x800 wait_id=135 seq_num=136 snap_id=1 wait times: snap=0.000219 sec, exc=0.000219 sec, total=0.000219 sec wait times: max=infinite wait counts: calls=0 os=0 occurred after 0.002586 sec of elapsed time 9: waited for 'log file sequential read' log#=0x28a9, block#=0x0, blocks=0x0 wait_id=134 seq_num=135 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.000141 sec of elapsed time Sampled Session History of session 233 serial 26991 --------------------------------------------------- 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:02 - 22:00:08] not in wait at each sample [1 sample, 22:00:01] 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-06-26 22:00:09.199 ------------------------------------------------------------------------------- Trace Bucket Dump Begin: default bucket for process 29 (osid: 580, J003) TIME(*=approx):SEQ:COMPONENT:FILE@LINE:FUNCTION:SECT/DUMP: [EVENT#:PID:SID] DATA ------------------------------------------------------------------------------- 2025-06-26 01:00:04.729558 :A9A9EF10:db_trace:kst.c@698:kstpsodel(): [10280:29:0] kst: process state object about to be deleted 2025-06-26 01:00:04.738208 :A9A9EF13:db_trace:kst.c@673:kstipg(): [10280:29:0] kst: process state object created on 06-26 01:00:04.737 2025-06-26 01:00:04.738210 :A9A9EF14:db_trace:kst.c@679:kstipg(): [10280:29:0] kst: process info: ospid=9112 pso_num=29 pso_serial#=183 2025-06-26 01:00:04.738349 :A9A9EF15:db_trace:kso.c@4070:ksonfy(): [10420:29:0] kso: new process: pid=9112 (legacy spawn) 2025-06-26 01:00:04.744767 :A9A9EF16: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-06-26 01:00:04.744925 :A9A9EF1E:db_trace:ksl2.c@12699:ksliwat(): [10005:29:233] 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-06-26 01:00:04.745729 :A9A9EF1F:db_trace:kst.c@698:kstpsodel(): [10280:29:0] kst: process state object about to be deleted 2025-06-26 01:00:10.317599 :A9A9F104:db_trace:kst.c@673:kstipg(): [10280:29:0] kst: process state object created on 06-26 01:00:10.304 2025-06-26 01:00:10.317601 :A9A9F105:db_trace:kst.c@679:kstipg(): [10280:29:0] kst: process info: ospid=5876 pso_num=29 pso_serial#=184 2025-06-26 01:00:10.317734 :A9A9F106:db_trace:kso.c@4070:ksonfy(): [10420:29:0] kso: new process: pid=5876 (legacy spawn) 2025-06-26 01:00:10.339868 :A9A9F107: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-06-26 01:00:10.340038 :A9A9F10C:db_trace:ksl2.c@12699:ksliwat(): [10005:29:233] 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-06-26 01:00:10.340858 :A9A9F111:db_trace:kst.c@698:kstpsodel(): [10280:29:0] kst: process state object about to be deleted 2025-06-26 01:00:10.349480 :A9A9F114:db_trace:kst.c@673:kstipg(): [10280:29:0] kst: process state object created on 06-26 01:00:10.335 2025-06-26 01:00:10.349482 :A9A9F115:db_trace:kst.c@679:kstipg(): [10280:29:0] kst: process info: ospid=16496 pso_num=29 pso_serial#=185 2025-06-26 01:00:10.349619 :A9A9F116:db_trace:kso.c@4070:ksonfy(): [10420:29:0] kso: new process: pid=16496 (legacy spawn) 2025-06-26 01:00:10.356101 :A9A9F117: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-06-26 01:00:10.356266 :A9A9F120:db_trace:ksl2.c@12699:ksliwat(): [10005:29:233] 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-06-26 01:00:10.357069 :A9A9F121:db_trace:kst.c@698:kstpsodel(): [10280:29:0] kst: process state object about to be deleted 2025-06-26 01:00:11.531607 :A9A9F130:db_trace:kst.c@673:kstipg(): [10280:29:0] kst: process state object created on 06-26 01:00:11.522 2025-06-26 01:00:11.531609 :A9A9F131:db_trace:kst.c@679:kstipg(): [10280:29:0] kst: process info: ospid=12612 pso_num=29 pso_serial#=186 2025-06-26 01:00:11.531752 :A9A9F132:db_trace:kso.c@4070:ksonfy(): [10420:29:0] kso: new process: pid=12612 (legacy spawn) 2025-06-26 01:00:11.538223 :A9A9F133: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-06-26 01:00:11.538414 :A9A9F138:db_trace:ksl2.c@12699:ksliwat(): [10005:29:233] 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-06-26 01:00:11.539267 :A9A9F13D:db_trace:kst.c@698:kstpsodel(): [10280:29:0] kst: process state object about to be deleted 2025-06-26 01:00:27.441052 :A9A9F65E:db_trace:kst.c@673:kstipg(): [10280:29:0] kst: process state object created on 06-26 01:00:27.428 2025-06-26 01:00:27.441054 :A9A9F65F:db_trace:kst.c@679:kstipg(): [10280:29:0] kst: process info: ospid=13548 pso_num=29 pso_serial#=187 2025-06-26 01:00:27.441192 :A9A9F660:db_trace:kso.c@4070:ksonfy(): [10420:29:0] kso: new process: pid=13548 (legacy spawn) 2025-06-26 01:00:27.447637 :A9A9F661: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-06-26 01:00:27.447816 :A9A9F667:db_trace:ksl2.c@12699:ksliwat(): [10005:29:233] 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-06-26 01:00:27.448614 :A9A9F66B:db_trace:kst.c@698:kstpsodel(): [10280:29:0] kst: process state object about to be deleted 2025-06-26 08:00:24.861162 :A9CB0DE0:db_trace:kst.c@673:kstipg(): [10280:29:0] kst: process state object created on 06-26 08:00:24.858 2025-06-26 08:00:24.861163 :A9CB0DE1:db_trace:kst.c@679:kstipg(): [10280:29:0] kst: process info: ospid=15364 pso_num=29 pso_serial#=188 2025-06-26 08:00:24.861304 :A9CB0DE2:db_trace:kso.c@4093:ksonfy(): [10420:29:0] kso: new process: pid=15364 osp_idx=27 osp_ver=13447 osp_pg=0 (spawn #323882) 2025-06-26 08:00:24.861305 :A9CB0DE3:db_trace:kso.c@4099:ksonfy(): [10420:29:0] kso: new process: first_req_pid=3704 spawner_pid=3660 sga_crt_ts=x8A8A 2025-06-26 08:00:24.861306 :A9CB0DE4:db_trace:kso.c@4103:ksonfy(): [10420:29:0] kso: new process: pso_index=29 reservation=168 time=3900568032 2025-06-26 08:00:24.861306 :A9CB0DE5:db_trace:kso.c@4109:ksonfy(): [10420:29:0] kso: spawn diagnostics: queue time=0 secs 2025-06-26 08:00:24.861307 :A9CB0DE6:db_trace:kso.c@4111:ksonfy(): [10420:29:0] kso: spawn diagnostics: fork time=0 secs 2025-06-26 08:00:24.861307 :A9CB0DE7:db_trace:kso.c@4113:ksonfy(): [10420:29:0] kso: spawn diagnostics: exec time=0 secs 2025-06-26 08:00:24.861307 :A9CB0DE8:db_trace:kso.c@4115:ksonfy(): [10420:29:0] kso: spawn diagnostics: pre dbkc time=0 secs 2025-06-26 08:00:24.861308 :A9CB0DE9:db_trace:kso.c@4117:ksonfy(): [10420:29:0] kso: spawn diagnostics: post dbkc time=0 secs 2025-06-26 08:00:24.861807 :A9CB0DEA: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-06-26 08:00:24.861852 :A9CB0DF0: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-06-26 08:00:24.870528 :A9CB0E02:db_trace:kst.c@698:kstpsodel(): [10280:29:0] kst: process state object about to be deleted 2025-06-26 09:00:31.994524 :A9D0314D:db_trace:kst.c@673:kstipg(): [10280:29:0] kst: process state object created on 06-26 09:00:31.992 2025-06-26 09:00:31.994526 :A9D0314E:db_trace:kst.c@679:kstipg(): [10280:29:0] kst: process info: ospid=16004 pso_num=29 pso_serial#=189 2025-06-26 09:00:31.994654 :A9D0314F:db_trace:kso.c@4093:ksonfy(): [10420:29:0] kso: new process: pid=16004 osp_idx=27 osp_ver=13448 osp_pg=0 (spawn #324025) 2025-06-26 09:00:31.994655 :A9D03150:db_trace:kso.c@4099:ksonfy(): [10420:29:0] kso: new process: first_req_pid=3704 spawner_pid=3660 sga_crt_ts=x8A8A 2025-06-26 09:00:31.994655 :A9D03151:db_trace:kso.c@4103:ksonfy(): [10420:29:0] kso: new process: pso_index=29 reservation=169 time=3904175172 2025-06-26 09:00:31.994656 :A9D03152:db_trace:kso.c@4109:ksonfy(): [10420:29:0] kso: spawn diagnostics: queue time=0 secs 2025-06-26 09:00:31.994657 :A9D03153:db_trace:kso.c@4111:ksonfy(): [10420:29:0] kso: spawn diagnostics: fork time=0 secs 2025-06-26 09:00:31.994657 :A9D03154:db_trace:kso.c@4113:ksonfy(): [10420:29:0] kso: spawn diagnostics: exec time=0 secs 2025-06-26 09:00:31.994657 :A9D03155:db_trace:kso.c@4115:ksonfy(): [10420:29:0] kso: spawn diagnostics: pre dbkc time=0 secs 2025-06-26 09:00:31.994658 :A9D03156:db_trace:kso.c@4117:ksonfy(): [10420:29:0] kso: spawn diagnostics: post dbkc time=0 secs 2025-06-26 09:00:31.995143 :A9D03157: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-06-26 09:00:31.995183 :A9D0315D: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-06-26 09:00:32.003297 :A9D0317F:db_trace:kst.c@698:kstpsodel(): [10280:29:0] kst: process state object about to be deleted 2025-06-26 10:00:39.137303 :A9D4F815:db_trace:kst.c@673:kstipg(): [10280:29:0] kst: process state object created on 06-26 10:00:39.135 2025-06-26 10:00:39.137305 :A9D4F816:db_trace:kst.c@679:kstipg(): [10280:29:0] kst: process info: ospid=14200 pso_num=29 pso_serial#=190 2025-06-26 10:00:39.137436 :A9D4F817:db_trace:kso.c@4093:ksonfy(): [10420:29:0] kso: new process: pid=14200 osp_idx=27 osp_ver=13449 osp_pg=0 (spawn #324164) 2025-06-26 10:00:39.137437 :A9D4F818:db_trace:kso.c@4099:ksonfy(): [10420:29:0] kso: new process: first_req_pid=3704 spawner_pid=3660 sga_crt_ts=x8A8A 2025-06-26 10:00:39.137437 :A9D4F819:db_trace:kso.c@4103:ksonfy(): [10420:29:0] kso: new process: pso_index=29 reservation=170 time=3907782313 2025-06-26 10:00:39.137437 :A9D4F81A:db_trace:kso.c@4109:ksonfy(): [10420:29:0] kso: spawn diagnostics: queue time=0 secs 2025-06-26 10:00:39.137438 :A9D4F81B:db_trace:kso.c@4111:ksonfy(): [10420:29:0] kso: spawn diagnostics: fork time=0 secs 2025-06-26 10:00:39.137438 :A9D4F81C:db_trace:kso.c@4113:ksonfy(): [10420:29:0] kso: spawn diagnostics: exec time=0 secs 2025-06-26 10:00:39.137438 :A9D4F81D:db_trace:kso.c@4115:ksonfy(): [10420:29:0] kso: spawn diagnostics: pre dbkc time=0 secs 2025-06-26 10:00:39.137439 :A9D4F81E:db_trace:kso.c@4117:ksonfy(): [10420:29:0] kso: spawn diagnostics: post dbkc time=0 secs 2025-06-26 10:00:39.137986 :A9D4F81F: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-06-26 10:00:39.138029 :A9D4F825: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-06-26 10:00:39.146079 :A9D4F847:db_trace:kst.c@698:kstpsodel(): [10280:29:0] kst: process state object about to be deleted 2025-06-26 11:00:46.770333 :A9D9B40C:db_trace:kst.c@673:kstipg(): [10280:29:0] kst: process state object created on 06-26 11:00:46.768 2025-06-26 11:00:46.770334 :A9D9B40D:db_trace:kst.c@679:kstipg(): [10280:29:0] kst: process info: ospid=13220 pso_num=29 pso_serial#=191 2025-06-26 11:00:46.770475 :A9D9B40E:db_trace:kso.c@4093:ksonfy(): [10420:29:0] kso: new process: pid=13220 osp_idx=27 osp_ver=13450 osp_pg=0 (spawn #324302) 2025-06-26 11:00:46.770476 :A9D9B40F:db_trace:kso.c@4099:ksonfy(): [10420:29:0] kso: new process: first_req_pid=3704 spawner_pid=3660 sga_crt_ts=x8A8A 2025-06-26 11:00:46.770476 :A9D9B410:db_trace:kso.c@4103:ksonfy(): [10420:29:0] kso: new process: pso_index=29 reservation=171 time=3911389954 2025-06-26 11:00:46.770477 :A9D9B411:db_trace:kso.c@4109:ksonfy(): [10420:29:0] kso: spawn diagnostics: queue time=0 secs 2025-06-26 11:00:46.770478 :A9D9B412:db_trace:kso.c@4111:ksonfy(): [10420:29:0] kso: spawn diagnostics: fork time=0 secs 2025-06-26 11:00:46.770478 :A9D9B413:db_trace:kso.c@4113:ksonfy(): [10420:29:0] kso: spawn diagnostics: exec time=0 secs 2025-06-26 11:00:46.770478 :A9D9B414:db_trace:kso.c@4115:ksonfy(): [10420:29:0] kso: spawn diagnostics: pre dbkc time=0 secs 2025-06-26 11:00:46.770479 :A9D9B415:db_trace:kso.c@4117:ksonfy(): [10420:29:0] kso: spawn diagnostics: post dbkc time=0 secs 2025-06-26 11:00:46.770979 :A9D9B416: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-06-26 11:00:46.771024 :A9D9B41C: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-06-26 11:00:46.779414 :A9D9B42E:db_trace:kst.c@698:kstpsodel(): [10280:29:0] kst: process state object about to be deleted 2025-06-26 12:00:54.311459 :A9DE6E05:db_trace:kst.c@673:kstipg(): [10280:29:0] kst: process state object created on 06-26 12:00:54.308 2025-06-26 12:00:54.311460 :A9DE6E06:db_trace:kst.c@679:kstipg(): [10280:29:0] kst: process info: ospid=17392 pso_num=29 pso_serial#=192 2025-06-26 12:00:54.311601 :A9DE6E07:db_trace:kso.c@4093:ksonfy(): [10420:29:0] kso: new process: pid=17392 osp_idx=27 osp_ver=13451 osp_pg=0 (spawn #324441) 2025-06-26 12:00:54.311602 :A9DE6E08:db_trace:kso.c@4099:ksonfy(): [10420:29:0] kso: new process: first_req_pid=3704 spawner_pid=3660 sga_crt_ts=x8A8A 2025-06-26 12:00:54.311602 :A9DE6E09:db_trace:kso.c@4103:ksonfy(): [10420:29:0] kso: new process: pso_index=29 reservation=172 time=3914997485 2025-06-26 12:00:54.311603 :A9DE6E0A:db_trace:kso.c@4109:ksonfy(): [10420:29:0] kso: spawn diagnostics: queue time=0 secs 2025-06-26 12:00:54.311603 :A9DE6E0B:db_trace:kso.c@4111:ksonfy(): [10420:29:0] kso: spawn diagnostics: fork time=0 secs 2025-06-26 12:00:54.311603 :A9DE6E0C:db_trace:kso.c@4113:ksonfy(): [10420:29:0] kso: spawn diagnostics: exec time=0 secs 2025-06-26 12:00:54.311604 :A9DE6E0D:db_trace:kso.c@4115:ksonfy(): [10420:29:0] kso: spawn diagnostics: pre dbkc time=0 secs 2025-06-26 12:00:54.311604 :A9DE6E0E:db_trace:kso.c@4117:ksonfy(): [10420:29:0] kso: spawn diagnostics: post dbkc time=0 secs 2025-06-26 12:00:54.312109 :A9DE6E0F: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-06-26 12:00:54.312150 :A9DE6E15: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-06-26 12:00:54.320121 :A9DE6E27:db_trace:kst.c@698:kstpsodel(): [10280:29:0] kst: process state object about to be deleted 2025-06-26 16:00:24.970796 :A9F1510A:db_trace:kst.c@673:kstipg(): [10280:29:0] kst: process state object created on 06-26 16:00:24.957 2025-06-26 16:00:24.970798 :A9F1510B:db_trace:kst.c@679:kstipg(): [10280:29:0] kst: process info: ospid=6220 pso_num=29 pso_serial#=193 2025-06-26 16:00:24.970937 :A9F1510C:db_trace:kso.c@4093:ksonfy(): [10420:29:0] kso: new process: pid=6220 osp_idx=27 osp_ver=13452 osp_pg=0 (spawn #324993) 2025-06-26 16:00:24.970937 :A9F1510D:db_trace:kso.c@4099:ksonfy(): [10420:29:0] kso: new process: first_req_pid=3704 spawner_pid=3660 sga_crt_ts=x8A8A 2025-06-26 16:00:24.970938 :A9F1510E:db_trace:kso.c@4103:ksonfy(): [10420:29:0] kso: new process: pso_index=29 reservation=173 time=3929368157 2025-06-26 16:00:24.970938 :A9F1510F:db_trace:kso.c@4109:ksonfy(): [10420:29:0] kso: spawn diagnostics: queue time=0 secs 2025-06-26 16:00:24.970939 :A9F15110:db_trace:kso.c@4111:ksonfy(): [10420:29:0] kso: spawn diagnostics: fork time=0 secs 2025-06-26 16:00:24.970939 :A9F15111:db_trace:kso.c@4113:ksonfy(): [10420:29:0] kso: spawn diagnostics: exec time=0 secs 2025-06-26 16:00:24.970939 :A9F15112:db_trace:kso.c@4115:ksonfy(): [10420:29:0] kso: spawn diagnostics: pre dbkc time=0 secs 2025-06-26 16:00:24.970939 :A9F15113:db_trace:kso.c@4117:ksonfy(): [10420:29:0] kso: spawn diagnostics: post dbkc time=0 secs 2025-06-26 16:00:24.971439 :A9F15114: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-06-26 16:00:24.971497 :A9F1511A: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-06-26 16:00:24.979155 :A9F15128: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-06-26 16:00:24.980214 :A9F15130: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-06-26 16:00:24.980860 :A9F15138: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-06-26 16:00:24.981360 :A9F15140: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-06-26 16:00:24.981792 :A9F15148: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-06-26 16:00:24.984195 :A9F15150: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-06-26 16:00:24.985385 :A9F15158: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-06-26 16:00:25.035322 :A9F15160: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-06-26 16:00:25.036228 :A9F15168: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-06-26 16:00:25.036469 :A9F15170: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-06-26 16:00:25.036682 :A9F15178: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-06-26 16:00:25.038439 :A9F15180:db_trace:kst.c@698:kstpsodel(): [10280:29:0] kst: process state object about to be deleted 2025-06-26 22:00:02.048402 :AA0DB1E8:db_trace:kst.c@673:kstipg(): [10280:29:0] kst: process state object created on 06-26 22:00:02.036 2025-06-26 22:00:02.048403 :AA0DB1E9:db_trace:kst.c@679:kstipg(): [10280:29:0] kst: process info: ospid=580 pso_num=29 pso_serial#=194 2025-06-26 22:00:02.048523 :AA0DB1EA:db_trace:kso.c@4093:ksonfy(): [10420:29:0] kso: new process: pid=580 osp_idx=27 osp_ver=13453 osp_pg=0 (spawn #325826) 2025-06-26 22:00:02.048523 :AA0DB1EB:db_trace:kso.c@4099:ksonfy(): [10420:29:0] kso: new process: first_req_pid=4308 spawner_pid=3660 sga_crt_ts=x8A8A 2025-06-26 22:00:02.048524 :AA0DB1EC:db_trace:kso.c@4103:ksonfy(): [10420:29:0] kso: new process: pso_index=29 reservation=174 time=3950945235 2025-06-26 22:00:02.048524 :AA0DB1ED:db_trace:kso.c@4109:ksonfy(): [10420:29:0] kso: spawn diagnostics: queue time=0 secs 2025-06-26 22:00:02.048525 :AA0DB1EE:db_trace:kso.c@4111:ksonfy(): [10420:29:0] kso: spawn diagnostics: fork time=0 secs 2025-06-26 22:00:02.048525 :AA0DB1EF:db_trace:kso.c@4113:ksonfy(): [10420:29:0] kso: spawn diagnostics: exec time=0 secs 2025-06-26 22:00:02.048525 :AA0DB1F0:db_trace:kso.c@4115:ksonfy(): [10420:29:0] kso: spawn diagnostics: pre dbkc time=0 secs 2025-06-26 22:00:02.048526 :AA0DB1F1:db_trace:kso.c@4117:ksonfy(): [10420:29:0] kso: spawn diagnostics: post dbkc time=0 secs 2025-06-26 22:00:02.049065 :AA0DB1F2: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-06-26 22:00:02.054038 :AA0DB218: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-06-26 22:00:02.054065 :AA0DB21B:db_trace:ktc.c@8711:ktcAutoTxnTrace(): [10441:29:233] atxpus:jslv.c:9203 2025-06-26 22:00:02.072339 :AA0DB3FF: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-06-26 22:00:02.072550 :AA0DB407: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-06-26 22:00:02.072730 :AA0DB40F: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-06-26 22:00:02.072891 :AA0DB417: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-06-26 22:00:02.073071 :AA0DB41F: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-06-26 22:00:02.073430 :AA0DB427: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-06-26 22:00:02.073633 :AA0DB42F: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-06-26 22:00:02.073791 :AA0DB437: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-06-26 22:00:02.074052 :AA0DB43F: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-06-26 22:00:02.074302 :AA0DB447: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-06-26 22:00:02.074668 :AA0DB44F: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-06-26 22:00:02.075146 :AA0DB457: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-06-26 22:00:02.075535 :AA0DB45F: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-06-26 22:00:02.075737 :AA0DB467: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-06-26 22:00:02.075898 :AA0DB46F: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-06-26 22:00:02.076057 :AA0DB477: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-06-26 22:00:02.076207 :AA0DB47F: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-06-26 22:00:02.103178 :AA0DB487: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-06-26 22:00:03.614454*:AA0DB70E:sql_mon_query:keswx.c@6099:keswxCurPushMonitoring(begin): xsc=0x0000000031233AD0 estart=1750946402 eid=19780491 ctx=0x0000000777968158 cwh=0x0000000029A90AB8 cpu=0 buffg=2 interb=0 r=0 rb=0 w=0 wb=0 2025-06-26 22:00:03.614454*:AA0DB710:sql_mon_query:keswx.c@2839:keswxCurPrepare(): Allocate monitor context: xsc=0x0000000031233AD0 curCtx=0x0000000048D3C4B8 pubTabIdxCnt=0 2025-06-26 22:00:03.614454*:AA0DB711:sql_mon_query:keswx.c@6131:keswxCurPushMonitoring(): clear monitoring flag for xsc=0x0000000031233AD0 2025-06-26 22:00:03.614454*:AA0DB714:sql_mon_query:keswx.c@6263:keswxCurPushMonitoring(end): full monitoring not yet started for xsc=0x0000000031233AD0 2025-06-26 22:00:03.614454*:AA0DB715:sql_mon_query:keswx.c@6099:keswxCurPushMonitoring(begin): xsc=0x000000003127AAF8 estart=1750946401 eid=16777414 ctx=0x000000077B54EAC8 cwh=0x0000000029A90608 cpu=1328125 buffg=72039 interb=196608 r=24 rb=196608 w=0 wb=0 2025-06-26 22:00:03.614454*:AA0DB717:sql_mon_query:keswx.c@2839:keswxCurPrepare(): Allocate monitor context: xsc=0x000000003127AAF8 curCtx=0x0000000048B51240 pubTabIdxCnt=0 2025-06-26 22:00:03.614454*:AA0DB718:sql_mon_query:keswx.c@6131:keswxCurPushMonitoring(): clear monitoring flag for xsc=0x000000003127AAF8 2025-06-26 22:00:03.614454*:AA0DB719:sql_mon_query:keswx.c@6263:keswxCurPushMonitoring(end): full monitoring not yet started for xsc=0x000000003127AAF8 2025-06-26 22:00:03.614454*:AA0DB71D:sql_mon_query:keswx.c@3282:keswxCurEndPlanMonitoringCb(begin): xsc=0x0000000031233AD0 curCtx=0x0000000048D3C4B8 xsc->flg4=65792 flags=1 2025-06-26 22:00:03.614454*:AA0DB71E:sql_mon_query:keswx.c@3389:keswxCurEndPlanMonitoringCb(end): monitoring has ended for xsc=0x0000000031233AD0 2025-06-26 22:00:03.770705*:AA0DB757:sql_mon_query:keswx.c@3282:keswxCurEndPlanMonitoringCb(begin): xsc=0x000000003127AAF8 curCtx=0x0000000048B51240 xsc->flg4=65792 flags=2 2025-06-26 22:00:03.770705*:AA0DB758:sql_mon_query:keswx.c@3389:keswxCurEndPlanMonitoringCb(end): monitoring has ended for xsc=0x000000003127AAF8 2025-06-26 22:00:03.778534 :AA0DB759: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-06-26 22:00:03.798806 :AA0DB792: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-06-26 22:00:03.800738 :AA0DB79A:db_trace:ktc.c@8711:ktcAutoTxnTrace(): [10441:29:233] atxpus:psdpgi.c:2235 2025-06-26 22:00:03.800945 :AA0DB79B:db_trace:ktc.c@8711:ktcAutoTxnTrace(): [10441:29:233] atxpop:psdpgi.c:2235 2025-06-26 22:00:03.801818 :AA0DB79C: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-06-26 22:00:03.801906 :AA0DB79F: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-06-26 22:00:03.802762 :AA0DB7B1: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-06-26 22:00:03.804184 :AA0DB7B9: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-06-26 22:00:03.804553 :AA0DB7C1: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-06-26 22:00:03.864469*:SQL_Analyze:qksan.c@3402:qksanAnalyzeSql(begin): qksanAnalyzeSql(enter): goal=15 options=16778048 pgadep=0 binds#=0 byPos=0 timeLim=0 timeFired=0 2025-06-26 22:00:03.864469*:SQL_Analyze:qksan.c@936:qksanBindSql(begin): binding for SQL analyze 2025-06-26 22:00:03.864469*:SQL_Analyze:qksan.c@1344:qksanBindSql(end): Done binding: status=0 ret=0 bind#=0 byPos=1 wasBoundP=0x0000000000000000 bindIndP=0x0000000000000000 2025-06-26 22:00:03.864469*:SQL_Analyze:qksan.c@6338:qksanAvgExecStats(): The number of total executions: 1 and execution count: 0 2025-06-26 22:00:03.864469*:SQL_Analyze:qksan.c@4776:qksanPostAnalyzeDump(begin): qksanPostAnalyzeDump(): Dumping analyze context after compilation qksanStatus=SUCCESS ecode=0 2025-06-26 22:00:03.864469*:SQL_Analyze:qksan.c@4800:qksanPostAnalyzeDump(end): 2025-06-26 22:00:03.864469*:SQL_Analyze:qksan.c@3690:qksanAnalyzeSql(end): exit: ecode=0 status=0 2025-06-26 22:00:03.943983 :AA0DB850: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-06-26 22:00:05.814346 :AA0DB9A6: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-06-26 22:00:05.814358 :AA0DB9A7:db_trace:ktur.c@3079:ktuabt(): [10444:29:233] ABORT TRANSACTION - xid: 0x0007.01d.0000c5c6 2025-06-26 22:00:08.231602 :AA0DBBC7: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-06-26 22:00:08.233525 :AA0DBBCF: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-06-26 22:00:08.245218 :AA0DBBD7: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-06-26 22:00:08.271944 :AA0DBBDF: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: 580, J003)