Sysadmin tales: Analyzing slow database server

Update:

• June 14th, 2016 6:01 PM UTC+7: using direct I/O or raw access also bypass filesystem caching. This also has effect to avoid double caching. I dare to guess Oracle does caching. So if everything cache, we would have: device caching, page cache, Oracle's own caching. Direct I/O eliminates page caching.

Dear readers

It's been awhile since my last post, so I guess I'll try to share something that might be useful for perfomance monitoring. This is something that I focus at now, and I found tightly related to OS knowledge. So please read on.

One day, I was urgently assigned by upper management to help identify certain (unknown) problem in Linux server. I quickly visited the site and did various checking.

The reported issue was that this server (a RHEL/CentOS one) was terribly slow at certain time. This server is running Oracle DB and running certain CRM software, as VM on top of VMWare. So slow that you barely could not do anything in ssh shell or interactive shell. And admins reported load average shoot to whooping 300-400 ("What the f**k?" Yeah I know, I was shocked too. 300 loadvg for few seconds was fine, but for minutes?). The machine itself has 30 core, by the way, so you can imagine this load is way too much

My quick guess was it was something related to I/O, to be specific disk read/write. Why? Because I/O code path mostly work in uninterruptible way. So once the calling process does read, for example, it will jump into kernel space and keep working until either it is finished or its scheduling interval is running out so it gets scheduled out.

Note: If the I/O is done in asynchronous style, the calling process could quickly return and continue executing next instruction. The work will be taken over by aio kernel thread and will trigger the callback mechanism back to the reading process once the read (or write) is finished. However, it is the aio thread that does the work now so system wise, the load would be the fairly the same. Only who does the work is different.

I check various logs, /proc entries and not to forgot, dmesg. Fortunately, I saw very enlightening hint there (not everyday I got this kind of clue at first sight, to be honest):

INFO: task oracle:22763 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

oracle D ffff81323c100600 0 22763 1 22779 22728 (NOTLB)

ffff810f0a3c3b88 0000000000000086 ffff812c3108e7b0 ffff81153c3ce100

ffff812c3108e7b0 0000000000000009 ffff812c3108e7b0 ffff8131ff133040

0000975e2fd08e7f 0000000000003e2c ffff812c3108e998 0000000c80063002

Call Trace:

[] do_gettimeofday+0x40/0x90

[] :jbd:start_this_handle+0x2e9/0x370

[] autoremove_wake_function+0x0/0x2e

[] :jbd:journal_start+0xcb/0x102

[] :ext3:ext3_dirty_inode+0x28/0x7b

[] __mark_inode_dirty+0x29/0x16e

[] do_generic_mapping_read+0x347/0x359

[] file_read_actor+0x0/0x159

[] __generic_file_aio_read+0x14c/0x198

[] generic_file_aio_read+0x36/0x3b

[] do_sync_read+0xc7/0x104

[] __dentry_open+0x101/0x1dc

[] autoremove_wake_function+0x0/0x2e

[] do_filp_open+0x2a/0x38

[] vfs_read+0xcb/0x171

[] sys_pread64+0x50/0x70

[] tracesys+0x71/0xdf

[] tracesys+0xd5/0xdf

Note: the above stack tracing happen automatically when kernel config CONFIG_DETECT_HUNG_TASK is enabled (=y). And this is enabled by default in RHEL/CentOS. So yes, this is an awesome feature and life saver.

What we can see is that it is starting as read operation (sys_pread). Then it is invoking read operation of virtual filesystem (vfs_read). Directory entry is opened then (dentry_open). It happens because before you open and access the file, you need to locate the directory that contains the file first.

Then the file is read in synchronous style. At this point, you might already suspect that this is the root cause. I partially agree. However, I am more concerned with the amount of data it is writing and how the Oracle database engine managed it.

Ok, let's move on. After usual marking inode as dirty (i am not sure about this, I guess it is dirty because access time metadata is updated, hence dirtying inode), and then journalling kicks in (jdb:journal start). Followed then by fetching current time (gettimeofday). And this is where things slow down.

First thing first. Getting local time shouldn't be that slow, even if you still count on PIT. HPET or TSC should be very fast. So getting time is out of equation.

Journalling is the next attention. Indeed that the filesystem Oracle puts data on is ext3. So for every write/read, journalling is updated so in the case of incidents, read/write could be replayed thus avoiding data corruption as much as possible.

Alright, so here is the early hypotheses. Oracle write huge amout of data, filesystem getting stressed. Journalling tries to keep up at the same speed. So who's to blame?

In my opinion, for database as sophisticated as Oracle, what they need is that bypassing filesystem layer. That could be implement by using O_DIRECT flag in read/write, or simply accessing raw device (e.g sda1 instead of /data for example). I am not sure which one is doable, but from operating system's point of view, those are the options.

Also, it is very worth to try to use noop I/O scheduler, instead of CFQ or deadline. The premise is same. Instead of letting filesystem layer manage the way Oracle works toward disk, why not just let it decide what is best for itself? Noop precisely do this. It is still does some I/O merging (front, back merge), but it doesn't do I/O prioritization, time out etc. So it feels almost like plain "I want to do it now!" and Linux kernel simple says "be my guest".

Other fact that I found, which is also shocking, is this (taken from /proc/meminfo):

PageTables: 116032004 kB

That's around 110 GiB, ladies and gentlemen, just to hold page tables! And don't forget that those page tables need to stay in RAM and can't be swapped out. So, simply speaking, 110 GiB of your RAM can't be used by your application and it might be your application that will be kicked out to swap in the event of shortage of free memory (before Out of Memory killer kicks in).

Thus, although not primary root cause, this must be solved too. The solution is to use huge page. This is the term to refer of using 2 MiB or 4 MiB (depending on page setting by kernel) page size instead of standar 4 KiB kernel uses. Let's assume later we will use 2 MiB page size and all allocated pages could fit into 2 MiB page size without fragmentation, then we could squeeze the PageTables usage by 512:1 ratio, or down to 0.2 GiB. Sounds good, right?

The full story might be boring, so hopefully I summarize it well enough for light study case.

Cross check result (by other team)

1. related team confirms that using asynchronous I/O together with direct I/O within Oracle relieve the load stress
2. Huge page is going to be tested. Not sure how it really goes since I am not updated, but I am sure, it will be helpful too

Until next time, cheerio! :)

regards,

Mulyadi Santosa

VirtualBox bugs: guest can not ping host and vice versa

Hi all

Happy New Year 2016. May God bless us with health and prosper.

Okay, just quick update. I found quite annoying fact: VirtualBox version 5.0.4 has bug: in bridged adapter mode, host can not ping guest VM and vice versa!

I googled about this and some people had early conclusion that it might be related to bugs in NDIS6 adapter.

However, there is easier workaround: just make sure you upgrade to latest version (version 5.0.12 as January 12th, 2016). Or, just stay in 4.3.x version. In my personal opinion, so far version 4.3.x ( which is still in active maintenance mode) is more stable than 5.0.x.

Hope it helps somebody out there.....

regards,

Mulyadi Santosa

Fixing segfault in Pathload

Dear readers

Couple days ago (it's 1st week of July 2012), I came across this nifty tool called Pathload. Essentially, it helps you determine the real upstream and downstream connection of yours.

Inaccidentally, when I tried to run it, it segfaulted immediately. With a bit help of gdb and trial/errors, I found and fix the bug. Here's the complete email message that I sent to its maintainer (which is I find no longer maintain it anymore) describing the problem. For those who just seek for the patch, just scroll to the end of this post (normal patch format):

Dear Constantinos

I came across this nice tool Pathload of yours today while exploring
about network management in Linux kernel. Of course, quickly I
downloaded the link to the source tarball (I use Linux -- Centos 5.x)
and compiled it.

When running it, it suddenly stopped due to segfault. After checking
the stack trace in the resulting core dump image, it leads to line 132
in client.c:
  strcpy(serverList[i],buf);

My intuition suddenly told me it must out of bound char copy. Short
story short, I landed to client.h at this line:
#define MAXDATASIZE 25 // max number of bytes we can get at once

I did quick test and change the above line. Now it reads
#define MAXDATASIZE 50

I do "make clean" followed by "make". Now it runs perfectly fine as
far as I can tell.

Hopefully it means something to you for upcoming release. Meanwhile,
once again thank you for this piece of good work.

PS: strangely, without modifying any single line of source code, the
resulting binary worked fine inside GNU debugger (gdb). That's why I
suspected a race condition initially.

--- client.h.old    2012-07-07 11:10:54.000000000 +0700
+++ client.h    2012-07-07 11:10:37.000000000 +0700
@@ -62,7 +62,7 @@
 #define UNCL    4

 #define SELECTPORT 55000 // the port client will be connecting to
-#define MAXDATASIZE 25 // max number of bytes we can get at once
+#define MAXDATASIZE 50 // max number of bytes we can get at once
 #define NUM_SELECT_SERVERS 3

 EXTERN int send_fleet() ;

"useradd" and "adduser" are the same? think again....

Well, actually they are not that different. Only small not-so-obvious-but-a-bit-bothering fact.

I did this in Ubuntu Natty (11.04):

sudo useradd -m user_a

and next:

sudo adduser -m user_b

Of course I put password on both of them, let's say "123456" (weak one, I know :) ). And then, if I did:

su - user_a

I got:

$

Just plain dollar sign. "Uhm, what's wrong?".

But, if I did:

su - user_b

I got:

user_b@localhost $

Grrrr.... I quickly concluded that something is different in their bash initialization. So a quick:

sudo diff -Naur /home/user_a/ /home/user_b/

should pin point the difference if there are any, right away. But I was wrong. They were exactly identical.

Then I decided to take a peek at /etc/passwd. No strong reason though, just plain curiousity:

grep -E 'user_a|user_b' /etc/passwd

the result:

user_a:..........:/bin/sh
user_b:..........:/bin/bash

[The passwd entries are shortened to focus on the important fields only]

Great! We found it! "But wait, isn't that /bin/sh a symbolic link to /bin/bash?". Well yes, at least sometimes ago. But recently, at least on latest releases of Ubuntu and its derivatives, /bin/sh is now pointing to "dash".

Dash is a "bash" alike shell but with smaller file size and fewer capability, which result to incompabilities with Bash in many aspects. So, no wonder that ".bashrc" didn't initialize the shell prompt along with other thing (enabling Tab completion, IIRC) correctly.

Therefore, to fix the useradd behaviour, simply use:

sudo useradd -s /bin/bash user_a

Another case closed, folks :)

PS: It's really a wonder how much you can do with grep and diff, if you know where to look ..... :D

NB:

regards,

Mulyadi Santosa

"libc.so.6 not found"? here we go again...

Hi all...

I've been tinkering with Linux Mint for the last month, so my CentOS installation was kinda abandoned. However, I took my chance to update CentOS via the usual chroot trick. It works.... however...

I found a glitch. I was aware of it when I ran my self-made wifi connection script which calls dhclient program. It said:

libc.so.6 not found

Great...ldd said the same thing too. However, libc.so.6 is still in /lib/libc.so.6, so it's not really missing. Hmmmm...

As a important note: recent update shows that there is another libc.so.6 which reside in /lib/i686/nosegneg. From random googling, I concluded that it is a "Xen friendly" library. It's a short way to describe that those libraries are not using certain segmentation techniques that might confuse or break Xen, so to speak.

Then, somehow I felt that it *might* be related to SELinux (i make it enforcing). Here are few lines from /var/log/messages that shows such quirk:
kernel: [    5.195941] type=1400 audit(1327499418.190:3):
 avc:  denied  { read } for  pid=860 comm="restorecon" name="libc.so.6" dev=xxxx ino=4821369 scontext=system_u:system_r:restorecon_t:s0 tcontext=system_u:object
_r:file_t:s0 tclass=lnk_file

and the output of "ls" is:

$ ls -lZ /lib/libc.so.6
 

lrwxrwxrwx  root root system_u:object_r:file_t          /lib/libc.so.6 -> libc-2.5.so
(the above output might be slightly incorrect, just focus on "file_t" attribute)

Alright, so SELinux attribute of libc.so.6 is wrong. I didn't know what exactly causing that during the chroot session. My best guess is that since it was done inside Linux Mint, which in turn doesn't use SELinux, partial relabeling or anything related to fix SELinux attribute simply fails.

The fix is fortunately easy:
1. edit /etc/sysconfig/selinux. change "SELINUX=enforcing" into "SELINUX=permissive"
2. do "sudo touch /.autorelabel". Notice the . (dot) prefix.
3. reboot

SELinux will relabel everything inside your mounted filesystem according to its default configuration once Linux enters normal runlevel.

To confirm your problem is gone, pick random binary, say dhclient and run ldd. Here's mine:
$  ldd /sbin/dhclient
libc.so.6 => /lib/i686/nosegneg/libc.so.6


And problem is solved :) Now you can turn SELinux back into enforcing mode.

PS: SELinux is both fun and frustating..... but with careful log analysis, usually you can pinpoint the root of the problem pretty fast.

regards,

Mulyadi Santosa

The correct gcc parameter for Intel Core Duo

On the quest of optimization....

One thing that bugs my mind lately is: which architecture Intel Core Duo uses? If we read this Wikipedia entry, one will quickly conclude that it is "enhanced" Pentium M.

So, does gcc agree with it? Not really. Using the idea taken from this blog entry, Core Duo is a Prescott! Here's the output:

/usr/lib/gcc/i486-linux-gnu/4.4.3/cc1 -E -quiet -v - -D_FORTIFY_SOURCE=2 -march=prescott --param l1-cache-size=32 --param l1-cache-line-size=64 --param l2-cache-size=2048 -mtune=generic -fstack-protector

Surprisingly, this is indeed correct. Gentoo's wiki page support this, even Intel's engineer puts amen.

Summary: I conclude, Core Duo it's Yonah (Pentium M), but optimization wise, assume it's Prescott.

regards,

Mulyadi Santosa

hashing? great.... which one?

Hi folks....

hashing is quite large subject. I myself simply use hash to confirm whether two files (or more) are identical or not (using md5sum, sha256sum).

But as the books say, hashing could has collisions. And hashing, one way or another, could be reversed. or in other word, there is no such perfect true one way hashing. Alright, we can't pursue perfection here. So what's the recipe to pick the best hashing method?

Fortunately, an article written by Valerie Aurora gives us the clue. For the impatient, you better use something like SHA-2 (sha256 or better). I found the article nicely explain the issues behind hashing with quite friendly (read: non hacker-ish) tone :)

Cheers and have a nice day ....

regards,

Mulyadi Santosa