Bug#647741: linux-image-3.0.0-2-amd64: UI sometimes freezes for several seconds, with a disk access
On 2012-02-21 14:03:56 +0000, Ben Hutchings wrote:
> There is a net increase of 5 processes over this period (186 -> 191).
> Maybe the extra disk activity comes from loading programs that aren't in
> cache?
The new processes during this period were:
PID PPID USERNAME GROUP STDATE STTIME ST EXC S CPU CMD
876 3257 vinc17 vinc17 2012/02/21 10:40:23 NE 0 E 0% <zsh>
877 876 vinc17 vinc17 2012/02/21 10:40:23 NE 0 E 0% <acpi>
878 3257 vinc17 vinc17 2012/02/21 10:40:24 NE 0 E 0% <ls>
879 3257 vinc17 vinc17 2012/02/21 10:40:24 NE 0 E 0% <zsh>
880 879 vinc17 vinc17 2012/02/21 10:40:24 NE 0 E 0% <acpi>
881 2660 root root 2012/02/21 10:40:24 NE 0 E 0% <ifconfig>
882 2 root root 2012/02/21 10:40:30 N- - S 0% kworker/1:3
883 2660 root root 2012/02/21 10:40:30 NE 0 E 0% <ifconfig>
884 3257 vinc17 vinc17 2012/02/21 10:40:33 N- - D 0% rsync
885 884 vinc17 vinc17 2012/02/21 10:40:34 N- - S 1% zsh
886 885 vinc17 vinc17 2012/02/21 10:40:34 NE 0 E 0% <zsh>
887 885 vinc17 vinc17 2012/02/21 10:40:34 NE 0 E 0% <zsh>
888 887 vinc17 vinc17 2012/02/21 10:40:34 NE 0 E 0% <zsh>
889 885 vinc17 vinc17 2012/02/21 10:40:34 NE 0 E 0% <locale>
890 889 vinc17 vinc17 2012/02/21 10:40:34 NE 127 E 0% <zsh>
891 885 vinc17 vinc17 2012/02/21 10:40:34 NE 0 E 0% <zsh>
892 885 vinc17 vinc17 2012/02/21 10:40:34 NE 127 E 0% <zsh>
893 892 vinc17 vinc17 2012/02/21 10:40:34 NE 0 E 0% <zsh>
894 885 vinc17 vinc17 2012/02/21 10:40:34 NE 0 E 0% <nproc>
895 885 vinc17 vinc17 2012/02/21 10:40:34 NE 0 E 0% <chmod>
896 885 vinc17 vinc17 2012/02/21 10:40:34 NE 0 E 0% <ls>
897 885 vinc17 vinc17 2012/02/21 10:40:34 NE 0 E 0% <head>
898 885 vinc17 vinc17 2012/02/21 10:40:34 NE 0 E 0% <ssh-add>
899 885 vinc17 vinc17 2012/02/21 10:40:34 N- - S 0% ssh
900 899 vinc17 vinc17 2012/02/21 10:40:34 N- - S 0% ssh
901 2660 root root 2012/02/21 10:40:34 NE 0 E 0% <ifconfig>
I recall that the disk started to become busy at 10:40:25.
There are no big programs. So I don't see why such a disk activity.
zsh is my shell, so that it should be more or less permanently in
cache.
At about 10:40:25 - 10:40:32, I started a rsync ($RSYNC_RSH is a
zsh wrapper to ssh, hence the processes 885 to 900), but I got no
output at all for several seconds (which is very unusual... except
when this disk activity problem occurs).
If I ask atop for disk details:
10:40:22
DSK | sda | busy 87% | read 121 | write 0 | avio 7 ms |
PID RDDSK WRDSK WRDSK_CANCEL DSK CMD 1/4
869 4408K 276K 0K 100% perl
31822 0K 16K 0K 0% atop
10:40:23
DSK | sda | busy 33% | read 54 | write 0 | avio 6 ms |
PID RDDSK WRDSK WRDSK_CANCEL DSK CMD 1/4
3257 5264K 448K 276K 100% zsh
31822 0K 20K 0K 0% atop
10:40:24
PID RDDSK WRDSK WRDSK_CANCEL DSK CMD 1/4
31822 0K 16K 0K 100% atop
10:40:25
DSK | sda | busy 16% | read 0 | write 123 | avio 1 ms |
PID RDDSK WRDSK WRDSK_CANCEL DSK CMD 1/4
317 0K 120K 0K 86% kjournald
31822 0K 20K 0K 14% atop
10:40:26
DSK | sda | busy 83% | read 0 | write 380 | avio 2 ms |
PID RDDSK WRDSK WRDSK_CANCEL DSK CMD 1/4
31822 0K 16K 0K 100% atop
10:40:27
DSK | sda | busy 100% | read 0 | write 245 | avio 4 ms |
PID RDDSK WRDSK WRDSK_CANCEL DSK CMD 1/4
31822 0K 16K 0K 100% atop
10:40:28
DSK | sda | busy 100% | read 0 | write 211 | avio 4 ms |
PID RDDSK WRDSK WRDSK_CANCEL DSK CMD 1/4
31822 0K 16K 0K 100% atop
10:40:29
DSK | sda | busy 100% | read 0 | write 291 | avio 3 ms |
PID RDDSK WRDSK WRDSK_CANCEL DSK CMD 1/4
31822 0K 20K 0K 100% atop
10:40:30
DSK | sda | busy 101% | read 0 | write 368 | avio 2 ms |
PID RDDSK WRDSK WRDSK_CANCEL DSK CMD 1/5
31822 0K 16K 0K 100% atop
10:40:31
DSK | sda | busy 101% | read 0 | write 466 | avio 2 ms |
PID RDDSK WRDSK WRDSK_CANCEL DSK CMD 1/5
31822 0K 16K 0K 100% atop
10:40:32
DSK | sda | busy 101% | read 0 | write 425 | avio 2 ms |
PID RDDSK WRDSK WRDSK_CANCEL DSK CMD 1/5
31822 0K 24K 0K 100% atop
10:40:33
DSK | sda | busy 99% | read 3 | write 273 | avio 3 ms |
PID RDDSK WRDSK WRDSK_CANCEL DSK CMD 1/4
884 92K 0K 0K 85% rsync
31822 0K 16K 0K 15% atop
10:40:34
DSK | sda | busy 98% | read 23 | write 133 | avio 6 ms |
PID RDDSK WRDSK WRDSK_CANCEL DSK CMD 1/5
884 308K 0K 0K 92% rsync
31822 0K 16K 0K 5% atop
1429 0K 8K 0K 2% rsyslogd
317 0K 4K 0K 1% kjournald
10:40:35
PID RDDSK WRDSK WRDSK_CANCEL DSK CMD 1/5
31822 0K 24K 0K 100% atop
10:40:36
DSK | sda | busy 0% | read 0 | write 1 | avio 0 ms |
PID RDDSK WRDSK WRDSK_CANCEL DSK CMD 1/5
31822 0K 16K 0K 100% atop
--
Vincent Lefèvre <vincent@vinc17.net> - Web: <http://www.vinc17.net/>
100% accessible validated (X)HTML - Blog: <http://www.vinc17.net/blog/>
Work: CR INRIA - computer arithmetic / AriC project (LIP, ENS-Lyon)
Reply to: