Getting a lot of unexpected io

qlands · 08-04-2012, 11:34 PM

Hi,

I am experiencing a lot of unexpected io in my machine. I have a 64bits, Core I7, 8 GB system with Slackware 13.37.

If I open for example QTCreator and close it just after I open it, I can see the second hard disk (sdb) working a lot and QTCreator hangs for few secods. I ran iostats at that moment and I get the following:

Code:

device mgr/s mgw/s    r/s    w/s    kr/s    kw/s   size queue   wait svc_t  %b     <- Starts closing
sda        0     0    0.0    0.0     0.0     0.0    0.0   0.0    0.0   0.0   0 
sdb        0     0    0.0    0.0     0.0     0.0    0.0   0.2    0.0   0.0  16 
                             extended device statistics                       
device mgr/s mgw/s    r/s    w/s    kr/s    kw/s   size queue   wait svc_t  %b 
sda        0     0    0.0    0.0     0.0     0.0    0.0   0.0    0.0   0.0   0 
sdb        0     0    0.0    0.0     0.0     0.0    0.0   1.0    0.0   0.0 100 
                             extended device statistics                       
device mgr/s mgw/s    r/s    w/s    kr/s    kw/s   size queue   wait svc_t  %b 
sda        0     0    0.0    0.0     0.0     0.0    0.0   0.0    0.0   0.0   0 
sdb        0     0    0.0    0.0     0.0     0.0    0.0   1.0    0.0   0.0 100 
                             extended device statistics                       
device mgr/s mgw/s    r/s    w/s    kr/s    kw/s   size queue   wait svc_t  %b 
sda        0     0    0.0    0.0     0.0     0.0    0.0   0.0    0.0   0.0   0 
sdb        0     0    0.0    0.0     0.0     0.0    0.0   1.1    0.0   0.0 100 
                             extended device statistics                       
device mgr/s mgw/s    r/s    w/s    kr/s    kw/s   size queue   wait svc_t  %b 
sda        0     0    0.0    0.0     0.0     0.0    0.0   0.0    0.0   0.0   0 
sdb        0    21    0.0   15.4     0.0    61.7    4.0  22.1  561.5  58.8  91 
                             extended device statistics                       
device mgr/s mgw/s    r/s    w/s    kr/s    kw/s   size queue   wait svc_t  %b 
sda        0     0    0.0    0.0     0.0     0.0    0.0   0.0    0.0   0.0   0 
sdb        0     0    0.0   22.5     0.0   171.9    7.7  12.2 1251.2  43.5  98 
                             extended device statistics                       
device mgr/s mgw/s    r/s    w/s    kr/s    kw/s   size queue   wait svc_t  %b 
sda        0     0    0.0    0.0     0.0     0.0    0.0   0.0    0.0   0.0   0 
sdb        0    14    0.0   22.3     0.0    97.2    4.4  22.1  546.4  45.5 100 
                             extended device statistics                       
device mgr/s mgw/s    r/s    w/s    kr/s    kw/s   size queue   wait svc_t  %b 
sda        0     0    0.0    0.0     0.0     0.0    0.0   0.0    0.0   0.0   0 
sdb        0     0    0.0   23.1     0.0   148.7    6.4   5.1  675.6  43.5 100 
                             extended device statistics                       
device mgr/s mgw/s    r/s    w/s    kr/s    kw/s   size queue   wait svc_t  %b 
sda        0     0    0.0    0.0     0.0     0.0    0.0   0.0    0.0   0.0   0 
sdb        0     0    0.0   22.3     0.0    89.0    4.0   3.3  198.7  45.5 100 
                             extended device statistics                       
device mgr/s mgw/s    r/s    w/s    kr/s    kw/s   size queue   wait svc_t  %b 
sda        0     0    0.0    0.0     0.0     0.0    0.0   0.0    0.0   0.0   0 
sdb        0     0    0.0   17.5     0.0    70.0    4.0   2.1  118.9  42.7  75 
                             extended device statistics                       
device mgr/s mgw/s    r/s    w/s    kr/s    kw/s   size queue   wait svc_t  %b 
sda        0     0    0.0    0.0     0.0     0.0    0.0   0.0    0.0   0.0   0 
sdb        0     0    0.0    0.0     0.0     0.0    0.0   0.0    0.0   0.0   0   <- End closing

I can see the hard disk 100 busy just by closing qtcreator.

Using iodump at the same moment I get:

Code:

TASK                   PID      TOTAL       READ      WRITE      DIRTY DEVICES
journald              2296        293          0        293          0 sdb3
flush-8:16           32604         63          0         63          0 sdb3, sdb1
kjournald             2294         19          0         19          0 sdb1
qtcreator            21722         13          0         13          0 sdb3

Both utilities point to sdb3. I don't get any messages in syslog or in messages. The df information is the following:

Code:

Filesystem     Type    1K-blocks     Used Available Use% Mounted on
/dev/root      ext3    137452716 14290704 116179764  11% /
/dev/sdb1      ext3    173023324 50169008 114065160  31% /data
/dev/sdb2      ext3     19228308  4753268  13498288  27% /usr/local
/dev/sdb3      ext3     48062468  6301428  39319564  14% /home
tmpfs          tmpfs     4082892        0   4082892   0% /dev/shm
/dev/sda2      fuseblk 102297596 72373860  29923736  71% /win7

What can I do to check what is happening?

Many thanks,
Carlos

Mark Pettit · 08-05-2012, 03:59 AM

Try 'iotop'. It will show you exact processes are writing to disk. I run it like this : iotop -o -d 5, which says only show processes doing actual i/o, and delay for 5 seconds to accumulate info. After that, once you see exactly what program is writing to disk (and you don't expect it to), you can use 'strace' to see exactly what is going on. You need to identify the process by it's pid - lets say it's pid 9999. The run 'strace -p 9999 -f'. This can generate a LOT of data if the process is very active, so consider redirecting to a file ( > /tmp/strace.txt). Finally, as it's really only disk-io you want to see, you can specify which system calls to trace, so, from the man page i see you can do this by appending '-e trace=open,close,read,write' to the strace command.