In the previous blog post<\/a>, I described a hanging issue caused by a debugging event in a Oracle 21c database. In a nutshell, the database writers started compulsively signaling each other to generate some debugging information. In the end, this non-DBWR work distracted the database writers so much that they completely neglected their core business – writing dirty blocks to files. The database writers were spending an extreme amount of time in the part of the code instrumented by the “oradebug request completion” wait event. In this article, I’ll describe the internals of this undocumented wait event. I conducted the research on a 21.5 database.<\/p>\n The first question is, how long does the execution of a single debugging event last? We can find that out by measuring the time between the Oracle C function calls kskthbwt and kskthewt. These functions mark the beginning and the end of a wait event, respectively. The second argument to kskthbwt is the event code, which can be queried from the data dictionary:<\/p>\n Now we can use this event code to filter only the event of interest:<\/p>\n We can see an outburst of 24 “oradebug request completion” events. The first occurrence was extreme – it lasted 5s, which is an eternity for a database writer. This is a serious issue.<\/p>\n The observed database writer process hasn’t spent almost any time on CPU – the cumulative CPU time for the process hasn’t changed:<\/p>\n Generally, high frequency stack sampling in regular intervals is a useful method to get an insight into a proprietary software. However, for a non-CPU-bound processes like this one, high frequency stack sampling might skew the picture because it would favor the code spending most time on CPU, but as the process isn’t CPU-bound, that might not be representative of where the time is being spent. Therefore, we must study off-CPU behavior as Gregg Brendan described it here<\/a>. His bcc program offcputime<\/a> takes a stack at each context switch and then aggregates the time this call stack spent blocking.<\/p>\n The following stack caused most off-CPU time:<\/p>\n However, in the stack above the database writer was only idly waiting and periodically waking up to check whether there’s something to do. We know this because of the functions semtimedop<\/span> and ksliwat<\/span> are on the stack, see Frits Hoogland’s presentation Profiling the logwriter and The following stack looks unusual and was causing high blocking time:<\/p>\n The program entered the syscall select and then was sleeping for a while (the function schedule_hrtimeout_range<\/a> is on the stack.)<\/p>\n The syscall select<\/a> checks multiple file descriptors if there is something to read or write. Without this system call, the application would need to monitor every file descriptor in a separate thread.<\/p>\n The arguments are as follows:<\/p>\n The system call receives three sets of file descriptors in the fd_set structures. nfds, the first argument, is highest-numbered file descriptor in any of the three sets, plus 1. Finally, the timeout parameter defines for how long to block the thread before waking up to check the file descriptors for input and output. From the Linux kernel function schedule_hrtimeout_range, we can infer that a non-zero timeout was passed to the syscall, and that the program spent a substantial amount of time doing nothing.<\/p>\n The following bpftrace script quantifies, how much time of the total wait event time was spent sleeping in the select syscall:<\/p>\n Out of 5000 ms spent in a oradebug wait event, 4599 ms were spent waiting in a select syscall.<\/p>\n Next, I inspected the individual select syscalls with bpftrace. bpftrace can access the following arguments of the select syscall:<\/p>\n In particular, I wanted to find the duration of each timeout, and how many file descriptors were being handled:<\/p>\n Surprisingly, there weren’t any file descriptors passed. This means that the select system call was used only to implement a sleep. The sleeping interval was 1 ms<\/span>.<\/p>\n strace flag -c can be used for profiling system calls:<\/p>\n We can see around 4000<\/span> executions for select\/open\/read\/close system<\/span> calls. By the way, don’t get confused the by the low times in seconds – it’s only the CPU time consumed by the syscall, not its duration. The profile looks like a loop that opens a file, reads it, closes it and then waits for 1 ms before the next iteration.<\/p>\n This pattern is visible in a more granular strace, where every syscall was traced.<\/p>\n The traced database writer was basically sampling \/proc\/PID\/stat file of the checkpoint process to generate some execution statistics:<\/p>\n Finally, I did some aggregations on the strace output:<\/p>\n Most \/proc\/PID\/stat samples (3634<\/span>) were on the ckpt process (with PID 1857715). This number seems excessive considering the 1 ms break between each sample. The database writer was being blocked for several seconds just by waiting between samples.<\/p>\n The rest of the reads were for other database writers, for example:<\/p>\n A performance problem with log switches can trigger database writers to generate debug information. This includes taking thousands of samples of \/proc\/PID\/stat for the checkpoint process. Since there’s a 1 ms sleep between each sample, it can take seconds to collect all the debugging information. This non-DBWR activity distracts database writers from their main work – writing dirty blocks to files. The consequences can be fatal – we observed a database grinded to a halt on several occasions.<\/p>\n The collection of diagnostic information is instrumented by the wait event “oradebug request completion”. If you see that the database writers are spending too much time in it, you can try increasing the undocumented parameter _log_switch_tracing_timeout to a much higher value, see my previous blog post<\/a>.<\/p>\n","protected":false},"excerpt":{"rendered":" Exploring the internals of the undocumented Oracle wait event “oradebug request completion” with eBPF. An example of an off-CPU analysis. Continue Reading select event#,name from v$event_name where name like 'oradebug request completion' ;\n\n EVENT# NAME\n---------- ----------------------------------------------------------------\n 588<\/span> oradebug request completion<\/code><\/pre>\nsudo bpftrace -e 'uprobe:\/u00\/oracle\/orabase\/product\/21.5.0.0.220131_a\/bin\/oracle:kskthbwt+2\n\/ pid == 1857586 && arg1 == 588<\/span> \/\n{\n @start[tid] = nsecs ;\n}\n\nuprobe:\/u00\/oracle\/orabase\/product\/21.5.0.0.220131_a\/bin\/oracle:kskthewt+2\n\/ @start[tid] \/\n{\n $duration_us = ( nsecs - @start[tid] ) \/ 1000 ;\n time(\"%H:%D:%S \");\n printf(\"duration [us] %d\\n\", $duration_us);\n delete(@start[tid])\n}'<\/code><\/pre>\n17:06\/10\/22:22 duration [us] 5002550<\/span>\n17:06\/10\/22:22 duration [us] 14\n17:06\/10\/22:22 duration [us] 5405\n17:06\/10\/22:22 duration [us] 4519\n17:06\/10\/22:22 duration [us] 4501\n17:06\/10\/22:22 duration [us] 4518\n17:06\/10\/22:22 duration [us] 5568\n17:06\/10\/22:22 duration [us] 5461\n17:06\/10\/22:22 duration [us] 6338\n17:06\/10\/22:22 duration [us] 5003\n17:06\/10\/22:22 duration [us] 4470\n17:06\/10\/22:22 duration [us] 8890\n17:06\/10\/22:22 duration [us] 5462\n17:06\/10\/22:22 duration [us] 5471\n17:06\/10\/22:22 duration [us] 5761\n17:06\/10\/22:22 duration [us] 5490\n17:06\/10\/22:22 duration [us] 4408\n17:06\/10\/22:22 duration [us] 4397\n17:06\/10\/22:22 duration [us] 5459\n17:06\/10\/22:22 duration [us] 7917\n17:06\/10\/22:22 duration [us] 5412\n17:06\/10\/22:22 duration [us] 4372\n17:06\/10\/22:22 duration [us] 5435\n17:06\/10\/22:22 duration [us] 4362\n...<\/code><\/pre>\nOff-CPU analysis<\/h1>\n
ps -p 1857586\n PID TTY TIME CMD\n1857586 ? 00:01:31 ora_dbw0_dbc<\/code><\/pre>\nsudo \/usr\/share\/bcc\/tools\/offcputime -p 1857586<\/code><\/pre>\nfinish_task_switch\nschedule\nschedule_timeout\ndo_semtimedop\nksys_semtimedop\n__x64_sys_semtimedop\ndo_syscall_64\nentry_SYSCALL_64_after_hwframe\nsemtimedop<\/span>\nskgpwwait\nksliwat<\/span>\nkslwaitctx\nksarcv\nksbabs\nksbrdp_int\nksbdispatch\nopirip\nopidrv\nsou2o\nopimai_real\nssthrdmain\nmain\n__libc_start_main\n[unknown]\n- ora_dbw0_dbc (1857586)\n\t39157040<\/code><\/pre>\n
\ndatabase writer<\/a> for more explanation. These stacks were collected before and after the actual problem happened.<\/p>\nfinish_task_switch\nschedule\nschedule_hrtimeout_range_clock\nschedule_hrtimeout_range<\/span>\npoll_schedule_timeout.constprop.16\ndo_select<\/span>\ncore_sys_select\nkern_select\n__x64_sys_select\ndo_syscall_64\nentry_SYSCALL_64_after_hwframe\n__libc_select\nksdx_cmdreq_wait\nksdx_cmdreq_wait_for_pending\nksdxdocmdmultex\nksdxdocmdmult\nksudmp_proc_short_stack\nkcbbckptmon\nksb_act_run_int\nksb_act_run\nksbcti\nksbabs\nksbrdp_int\nksbdispatch\nopirip\nopidrv\nsou2o\nopimai_real\nssthrdmain\nmain\n__libc_start_main\n[unknown]\n- ora_dbw0_dbc (1857586)\n\t4885099<\/code><\/pre>\nselect syscall<\/h1>\n
int select(int nfds, fd_set *restrict readfds,\n\t\t fd_set *restrict writefds, fd_set *restrict exceptfds,\n\t\t struct timeval *restrict timeout);<\/code><\/pre>\nsudo bpftrace -e 'uprobe:\/u00\/oracle\/orabase\/product\/21.5.0.0.220131_a\/bin\/oracle:kskthbwt+2\n\/ pid == 1857586 && arg1 == 588 \/\n{\n @start[tid] = nsecs ;\n}\n\ntracepoint:syscalls:sys_enter_select\n\/ @start[tid] \/\n{\n @start_select[tid] = nsecs ;\n}\n\ntracepoint:syscalls:sys_exit_select\n\/ @start_select[tid] \/\n{\n @duration_select_ms = sum( ( nsecs - @start_select[tid] ) \/ 1000 \/ 1000 );\n @count_select = count();\n delete(@start_select[tid]);\n}\n\nuprobe:\/u00\/oracle\/orabase\/product\/21.5.0.0.220131_a\/bin\/oracle:kskthewt+2\n\/ @start[tid] \/\n{\n $duration_ms = ( nsecs - @start[tid] ) \/ 1000 \/ 1000 ;\n printf(\"Duration wait event [ms] %d\\n\", $duration_ms);\n delete(@start[tid]);\n delete(@start_select[tid]);\n exit()\n}'<\/code><\/pre>\nDuration wait event [ms] 5000\n\n@count_select: 4612\n\n@duration_select_ms: 4599<\/code><\/pre>\nTracing select<\/h1>\n
sudo bpftrace -lv 'tracepoint:syscalls:sys_enter_select'\ntracepoint:syscalls:sys_enter_select\n int __syscall_nr\n int n\n fd_set * inp\n fd_set * outp\n fd_set * exp\n struct timeval * tvp<\/code><\/pre>\nsudo bpftrace -e 'tracepoint:syscalls:sys_enter_select\n\/ pid == 1857586 \/\n{\n printf(\"Number of file descriptors: %d Sleep: %d sec %d usec\\n\", args->n, args->tvp->tv_sec, args->tvp->tv_usec);\n}'<\/code><\/pre>\nNumber of file descriptors: 0<\/span> Sleep: 0 sec 1000 usec<\/span>\nNumber of file descriptors: 0 Sleep: 0 sec 1000 usec\nNumber of file descriptors: 0 Sleep: 0 sec 1000 usec\nNumber of file descriptors: 0 Sleep: 0 sec 1000 usec\nNumber of file descriptors: 0 Sleep: 0 sec 1000 usec\n...<\/code><\/pre>\nProfiling syscalls<\/h1>\n
sudo strace -f -c -p 1857676<\/code><\/pre>\n% time seconds usecs\/call calls errors syscall\n------ ----------- ----------- --------- --------- ----------------\n 33.06 0.116057 28 4049<\/span> openat<\/span>\n 23.29 0.081759 20 4047<\/span> read<\/span>\n 21.53 0.075589 19 3849<\/span> 6 select<\/span>\n 18.51 0.064976 16 4049 close<\/span>\n 1.92 0.006740 33 201 write\n 0.36 0.001268 24 51 lseek\n 0.36 0.001262 18 69 rt_sigprocmask\n 0.28 0.000995 41 24 24 semtimedop\n 0.23 0.000806 14 54 getrusage\n 0.15 0.000540 8 63 sched_yield\n 0.13 0.000452 19 23 tgkill\n 0.07 0.000256 11 23 22 rt_sigreturn\n 0.04 0.000151 30 5 lstat\n 0.03 0.000090 22 4 stat\n 0.02 0.000054 27 2 chown\n 0.01 0.000039 19 2 fcntl\n 0.01 0.000021 21 1 geteuid\n------ ----------- ----------- --------- --------- ----------------\n100.00 0.351055 21 16516 52 total<\/code><\/pre>\nsudo strace -o strace3.log -f -p 1857676<\/code><\/pre>\n...\n1857676 select(0, 0x7fff18135c90, 0x7fff18135c90, 0x7fff18135c90, {tv_sec=0, tv_usec=1000}) = 0 (Timeout)\n1857676 openat(AT_FDCWD, \"\/proc\/1857715\/stat\", O_RDONLY) = 11\n1857676 read(11, \"1857715 (ora_ckpt_dbc) S 1 18\"..., 999) = 332\n1857676 close(11) = 0\n1857676 select(0, 0x7fff18135c90, 0x7fff18135c90, 0x7fff18135c90, {tv_sec=0, tv_usec=1000}) = 0 (Timeout)\n1857676 openat(AT_FDCWD, \"\/proc\/1857715\/stat\", O_RDONLY) = 11\n1857676 read(11, \"1857715 (ora_ckpt_dbc) S 1 18\"..., 999) = 332\n1857676 close(11) = 0\n1857676 select(0, 0x7fff18135c90, 0x7fff18135c90, 0x7fff18135c90, {tv_sec=0, tv_usec=1000}) = 0 (Timeout)\n1857676 openat(AT_FDCWD, \"\/proc\/1857715\/stat\", O_RDONLY) = 11\n1857676 read(11, \"1857715 (ora_ckpt_dbc) S 1 18\"..., 999) = 332\n1857676 close(11) = 0\n1857676 select(0, 0x7fff18135c90, 0x7fff18135c90, 0x7fff18135c90, {tv_sec=0, tv_usec=1000}) = 0 (Timeout)\n1857676 openat(AT_FDCWD, \"\/proc\/1857715\/stat\", O_RDONLY) = 11\n1857676 read(11, \"1857715 (ora_ckpt_dbc) S 1 18\"..., 999) = 332\n1857676 close(11) = 0\n1857676 select(0, 0x7fff18135c90, 0x7fff18135c90, 0x7fff18135c90, {tv_sec=0, tv_usec=1000}) = 0 (Timeout)\n1857676 openat(AT_FDCWD, \"\/proc\/1857715\/stat\", O_RDONLY) = 11\n1857676 read(11, \"1857715 (ora_ckpt_dbc) S 1 18\"..., 999) = 332\n1857676 close(11) = 0\n...<\/code><\/pre>\nps -p 1857715\n PID TTY TIME CMD\n1857715 ? 00:05:25 ora_ckpt_dbc<\/code><\/pre>\nstrings strace3.log | grep open strace3.log | awk -F '\"' '{ print $2 }' | sort | uniq -c | sort -n -k 1<\/code><\/pre>\n...\n 12 \/proc\/1857683\/stat\n 14 \/proc\/1857597\/stat\n 14 \/proc\/1857641\/stat\n 14 \/proc\/1857689\/stat\n 14 \/proc\/1857705\/stat\n 15 \/proc\/1857623\/stat\n 15 \/proc\/1857633\/stat\n 15 \/proc\/1857655\/stat\n 15 \/proc\/1857666\/stat\n 15 \/proc\/1857685\/stat\n 15 \/proc\/1857696\/stat\n 16 \/proc\/1857586\/stat\n 16 \/proc\/1857588\/stat\n 16 \/proc\/1857600\/stat\n 16 \/proc\/1857608\/stat\n 16 \/proc\/1857619\/stat\n 16 \/proc\/1857657\/stat\n 16 \/proc\/1857663\/stat\n 16 \/proc\/1857668\/stat\n 16 \/proc\/1857674\/stat\n 16 \/proc\/1857692\/stat\n 16 \/proc\/1857699\/stat\n 16 \/proc\/1857701\/stat\n 3634<\/span> \/proc\/1857715\/stat<\/code><\/pre>\nps -p 1857701\n PID TTY TIME CMD\n1857701 ? 00:01:27 ora_dbwm_dbc\n\nps -p 1857699\n PID TTY TIME CMD\n1857699 ? 00:01:29 ora_dbwl_dbc<\/code><\/pre>\nSummary<\/h1>\n