Re: intermittent very high waits in LGWR on Linux?

From: bugbear <bugbear_at_trim_papermule.co.uk_trim>
Date: Fri, 01 Jul 2005 15:27:47 +0100
Message-ID: <42c552e8$0$17910$ed2619ec@ptn-nntp-reader02.plus.net>

bugbear wrote:
>
> It seems that I either get "correct" redo
> log write out, with times varying from 53 to 29177
> microseconds, or I "fallback" to some kind of quantized
> timeout write behavior, driven by a 1 second clock.

Nope. Not a 1 second "clock". A 1 second wait on a semaphore.

I put strace -tt on the ora_lgwr_scan process, and found this (excerpt from a MUCH larger file)

14:40:47.224180 pwrite(14, "u\5\0\0\255i\1\0oS\207!\20\0\3506\270\1\0\0\1\1\0\0I\254"..., 1536, 47405568) = 1536
14:40:47.224364 gettimeofday({1120225247, 224378}, {4294967236, 0}) = 0
14:40:47.224404 gettimeofday({1120225247, 224418}, {4294967236, 0}) = 0
14:40:47.224449 gettimeofday({1120225247, 224463}, {4294967236, 0}) = 0
14:40:47.224488 gettimeofday({1120225247, 224502}, {4294967236, 0}) = 0
14:40:47.224531 gettimeofday({1120225247, 224545}, {4294967236, 0}) = 0
14:40:47.224570 gettimeofday({1120225247, 224584}, {4294967236, 0}) = 0
14:40:47.224607 gettimeofday({1120225247, 224621}, {4294967236, 0}) = 0
14:40:47.224655 gettimeofday({1120225247, 224669}, {4294967236, 0}) = 0
14:40:47.224694 gettimeofday({1120225247, 224707}, {4294967236, 0}) = 0
14:40:47.224733 rt_sigprocmask(SIG_BLOCK, NULL, [RTMIN], 8) = 0
14:40:47.224776 rt_sigprocmask(SIG_BLOCK, [ALRM], NULL, 8) = 0
14:40:47.224816 gettimeofday({1120225247, 224830}, NULL) = 0
14:40:47.224851 setitimer(ITIMER_REAL, {it_interval={0, 0}, it_value={1, 380000}}, NULL) = 0
14:40:47.224890 rt_sigprocmask(SIG_UNBLOCK, [ALRM], NULL, 8) = 0

--->> 14:40:47.224930 semop(720898, 0xbfffe6b0, 1) = 0

14:40:48.245611 rt_sigprocmask(SIG_BLOCK, [ALRM], NULL, 8) = 0
14:40:48.245681 setitimer(ITIMER_REAL, {it_interval={0, 0}, it_value={0, 0}}, NULL) = 0
14:40:48.245723 rt_sigprocmask(SIG_UNBLOCK, [ALRM], NULL, 8) = 0
14:40:48.245765 gettimeofday({1120225248, 245780}, {4294967236, 0}) = 0
14:40:48.245822 gettimeofday({1120225248, 245836}, {4294967236, 0}) = 0
14:40:48.245873 gettimeofday({1120225248, 245888}, {4294967236, 0}) = 0
14:40:48.245921 gettimeofday({1120225248, 245935}, {4294967236, 0}) = 0
14:40:48.245960 pwrite(14, "u\5\0\0\260i\1\0pS\207!\20\0\273\33\210\1\0\0\1\1\0\0K"..., 1536, 47407104) = 1536

Note the feeble size of the write (that's my fault - all those commits you guy told me about).
Note the time elapsed between the writes - my (now famous!) second. NOTE THE semop() call (with the arrow). The second goes waiting (hence the lack of CPU) on a semaphore.

I've checked against the Oracle/Linux semaphore docs; I have;

ipcs -ls

• Semaphore Limits -------- max number of arrays = 128 max semaphores per array = 250 max semaphores system wide = 32000 max ops per semop call = 100 semaphore max value = 32767

which looks "ok" against these recs:
http://www.puschitz.com/TuningLinuxForOracle.shtml#SettingSemaphores

I'm still digging. Wether I'll find an answer or a deeper hole remains to be seen.

   BugBear Received on Fri Jul 01 2005 - 09:27:47 CDT