I have an odd situation here, after a recent reboot my system seemed *very* slow indeed, took ages to start the X desktop etc. and when I looked at the load average with 'uptime' it was over 5 which is pretty silly considering there is really nothing much happening.
While the X desktop was still thinking about appearing I ran a virtual console, logged in (even that was a bit slow) and ran tops. Tops reported virtually nothing consuming processor time.
So what's going on, why is my system slow, especially when starting, but nothing actually seems to be doing much.
This is a Core 2 Duo Quad core processor with 8Gb of memory so really should be quite quick - especially when doing nothing!
Running uptime now (40 minutes after power-up) the load average is 0.03 which is more like what I'd expect to see?
Is there any way to see what that load average is indicating?
On 27/06/10 17:51, Chris G wrote:
I have an odd situation here, after a recent reboot my system seemed *very* slow indeed, took ages to start the X desktop etc. and when I looked at the load average with 'uptime' it was over 5 which is pretty silly considering there is really nothing much happening.
While the X desktop was still thinking about appearing I ran a virtual console, logged in (even that was a bit slow) and ran tops. Tops reported virtually nothing consuming processor time.
So what's going on, why is my system slow, especially when starting, but nothing actually seems to be doing much.
This is a Core 2 Duo Quad core processor with 8Gb of memory so really should be quite quick - especially when doing nothing!
Running uptime now (40 minutes after power-up) the load average is 0.03 which is more like what I'd expect to see?
Is there any way to see what that load average is indicating?
I use gkrellm but unfortunately you won't see that until X is up which is too late for you.7
Cheers
Ian
On Sun, Jun 27, 2010 at 5:51 PM, Chris G cl@isbd.net wrote:
I have an odd situation here, after a recent reboot my system seemed *very* slow indeed...
Try installing bootchart[1] it's perfect for this kind of problem and packaged up in Debian, Ubuntu and Fedora. If it was just the once maybe it was due to a file system check at boot?
Hope that helps, Dennis
On Sun, Jun 27, 2010 at 06:21:45PM +0100, Dennis Dryden wrote:
On Sun, Jun 27, 2010 at 5:51 PM, Chris G cl@isbd.net wrote:
I have an odd situation here, after a recent reboot my system seemed *very* slow indeed...
Try installing bootchart[1] it's perfect for this kind of problem and packaged up in Debian, Ubuntu and Fedora. If it was just the once maybe it was due to a file system check at boot?
A file system check takes almost an hour on my system, that's not what it was! :-)
I'll try bootchart, sounds useful.
On Sun, Jun 27, 2010 at 09:25:28PM +0100, Chris G wrote:
On Sun, Jun 27, 2010 at 06:21:45PM +0100, Dennis Dryden wrote:
On Sun, Jun 27, 2010 at 5:51 PM, Chris G cl@isbd.net wrote:
I have an odd situation here, after a recent reboot my system seemed *very* slow indeed...
Try installing bootchart[1] it's perfect for this kind of problem and packaged up in Debian, Ubuntu and Fedora. If it was just the once maybe it was due to a file system check at boot?
A file system check takes almost an hour on my system, that's not what it was! :-)
I'll try bootchart, sounds useful.
... and it shows, amoung other things, that ureadahead sits for almost 20 seconds at startup in iowait with nothing else happening at all. Apart from that everything looks fairly normal.
On Sun, Jun 27, 2010 at 09:45:19PM +0100, Chris G wrote:
On Sun, Jun 27, 2010 at 09:25:28PM +0100, Chris G wrote:
On Sun, Jun 27, 2010 at 06:21:45PM +0100, Dennis Dryden wrote:
On Sun, Jun 27, 2010 at 5:51 PM, Chris G cl@isbd.net wrote:
I have an odd situation here, after a recent reboot my system seemed *very* slow indeed...
Try installing bootchart[1] it's perfect for this kind of problem and packaged up in Debian, Ubuntu and Fedora. If it was just the once maybe it was due to a file system check at boot?
A file system check takes almost an hour on my system, that's not what it was! :-)
I'll try bootchart, sounds useful.
... and it shows, amoung other things, that ureadahead sits for almost 20 seconds at startup in iowait with nothing else happening at all. Apart from that everything looks fairly normal.
... and dmesg shows the same delay:-
Jun 27 21:56:38 chris kernel: [ 2.842494] kjournald starting. Commit interval 5 seconds Jun 27 21:56:38 chris kernel: [ 2.842530] EXT3-fs: mounted filesystem with ordered data mode. Jun 27 21:56:38 chris kernel: [ 3.682882] type=1505 audit(1277672181.168:2): operation="profile_load" pid=443 name=/sbin/dhclien> Jun 27 21:56:38 chris kernel: [ 3.683497] type=1505 audit(1277672181.168:3): operation="profile_load" pid=443 name=/usr/lib/Netw> Jun 27 21:56:38 chris kernel: [ 3.683844] type=1505 audit(1277672181.178:4): operation="profile_load" pid=443 name=/usr/lib/conn> Jun 27 21:56:38 chris kernel: [ 3.718490] type=1505 audit(1277672181.208:5): operation="profile_load" pid=444 name=/usr/bin/evin> Jun 27 21:56:38 chris kernel: [ 3.728420] type=1505 audit(1277672181.218:6): operation="profile_load" pid=444 name=/usr/bin/evin> Jun 27 21:56:38 chris kernel: [ 3.734171] type=1505 audit(1277672181.228:7): operation="profile_load" pid=444 name=/usr/bin/evin> Jun 27 21:56:38 chris kernel: [ 3.755632] type=1505 audit(1277672181.248:8): operation="profile_load" pid=446 name=/usr/lib/cups> Jun 27 21:56:38 chris kernel: [ 3.756354] type=1505 audit(1277672181.248:9): operation="profile_load" pid=446 name=/usr/sbin/cup> Jun 27 21:56:38 chris kernel: [ 3.775301] type=1505 audit(1277672181.268:10): operation="profile_load" pid=447 name=/usr/sbin/my> Jun 27 21:56:38 chris kernel: [ 18.746128] udev: starting version 147 Jun 27 21:56:38 chris kernel: [ 18.763280] lp: driver loaded but no devices found Jun 27 21:56:38 chris kernel: [ 18.818800] Adding 19800072k swap on /dev/sda5. Priority:-1 extents:1 across:19800072k Jun 27 21:56:38 chris kernel: [ 18.851109] ip_tables: (C) 2000-2006 Netfilter Core Team Jun 27 21:56:38 chris kernel: [ 18.883661] r8169: eth0: link up Jun 27 21:56:38 chris kernel: [ 18.883667] r8169: eth0: link up Jun 27 21:56:38 chris kernel: [ 18.901562] alloc irq_desc for 22 on node 0 Jun 27 21:56:38 chris kernel: [ 18.901565] alloc kstat_irqs on node 0 Jun 27 21:56:38 chris kernel: [ 18.901574] HDA Intel 0000:00:1b.0: PCI INT A -> GSI 22 (level, low) -> IRQ 22 Jun 27 21:56:38 chris kernel: [ 18.901684] HDA Intel 0000:00:1b.0: setting latency timer to 64 Jun 27 21:56:38 chris kernel: [ 19.036644] input: HDA Digital PCBeep as /devices/pci0000:00/0000:00:1b.0/input/input5 Jun 27 21:56:38 chris kernel: [ 19.493924] EXT3 FS on sda1, internal journal Jun 27 21:56:38 chris kernel: [ 20.608497] kjournald starting. Commit interval 5 seconds
OK, it's a 15 second delay but still doing nothing for 15 seconds does seem a bit excessive.
On 27-Jun-10 21:09:59, Chris G wrote:
On Sun, Jun 27, 2010 at 09:45:19PM +0100, Chris G wrote:
On Sun, Jun 27, 2010 at 09:25:28PM +0100, Chris G wrote:
On Sun, Jun 27, 2010 at 06:21:45PM +0100, Dennis Dryden wrote:
On Sun, Jun 27, 2010 at 5:51 PM, Chris G cl@isbd.net wrote:
I have an odd situation here, after a recent reboot my system seemed *very* slow indeed...
Try installing bootchart[1] it's perfect for this kind of problem and packaged up in Debian, Ubuntu and Fedora. If it was just the once maybe it was due to a file system check at boot?
A file system check takes almost an hour on my system, that's not what it was! :-)
I'll try bootchart, sounds useful.
... and it shows, amoung other things, that ureadahead sits for almost 20 seconds at startup in iowait with nothing else happening at all. Apart from that everything looks fairly normal.
... and dmesg shows the same delay:-
Jun 27 21:56:38 chris kernel: [ 2.842494] kjournald starting.Commit interval 5 seconds Jun 27 21:56:38 chris kernel: [ 2.842530] EXT3-fs: mounted filesystem with ordered data mode. Jun 27 21:56:38 chris kernel: [ 3.682882] type=1505 audit(1277672181.168:2): operation="profile_load" pid=443 name=/sbin/dhclien> Jun 27 21:56:38 chris kernel: [ 3.683497] type=1505 audit(1277672181.168:3): operation="profile_load" pid=443 name=/usr/lib/Netw> Jun 27 21:56:38 chris kernel: [ 3.683844] type=1505 audit(1277672181.178:4): operation="profile_load" pid=443 name=/usr/lib/conn> Jun 27 21:56:38 chris kernel: [ 3.718490] type=1505 audit(1277672181.208:5): operation="profile_load" pid=444 name=/usr/bin/evin> Jun 27 21:56:38 chris kernel: [ 3.728420] type=1505 audit(1277672181.218:6): operation="profile_load" pid=444 name=/usr/bin/evin> Jun 27 21:56:38 chris kernel: [ 3.734171] type=1505 audit(1277672181.228:7): operation="profile_load" pid=444 name=/usr/bin/evin> Jun 27 21:56:38 chris kernel: [ 3.755632] type=1505 audit(1277672181.248:8): operation="profile_load" pid=446 name=/usr/lib/cups> Jun 27 21:56:38 chris kernel: [ 3.756354] type=1505 audit(1277672181.248:9): operation="profile_load" pid=446 name=/usr/sbin/cup> Jun 27 21:56:38 chris kernel: [ 3.775301] type=1505 audit(1277672181.268:10): operation="profile_load" pid=447 name=/usr/sbin/my> Jun 27 21:56:38 chris kernel: [ 18.746128] udev: starting version 147 Jun 27 21:56:38 chris kernel: [ 18.763280] lp: driver loaded but no devices found Jun 27 21:56:38 chris kernel: [ 18.818800] Adding 19800072k swap on /dev/sda5. Priority:-1 extents:1 across:19800072k Jun 27 21:56:38 chris kernel: [ 18.851109] ip_tables: (C) 2000-2006 Netfilter Core Team Jun 27 21:56:38 chris kernel: [ 18.883661] r8169: eth0: link up Jun 27 21:56:38 chris kernel: [ 18.883667] r8169: eth0: link up Jun 27 21:56:38 chris kernel: [ 18.901562] alloc irq_desc for 22 on node 0 Jun 27 21:56:38 chris kernel: [ 18.901565] alloc kstat_irqs on node 0 Jun 27 21:56:38 chris kernel: [ 18.901574] HDA Intel 0000:00:1b.0: PCI INT A -> GSI 22 (level, low) -> IRQ 22 Jun 27 21:56:38 chris kernel: [ 18.901684] HDA Intel 0000:00:1b.0: setting latency timer to 64 Jun 27 21:56:38 chris kernel: [ 19.036644] input: HDA Digital PCBeep as /devices/pci0000:00/0000:00:1b.0/input/input5 Jun 27 21:56:38 chris kernel: [ 19.493924] EXT3 FS on sda1, internal journal Jun 27 21:56:38 chris kernel: [ 20.608497] kjournald starting. Commit interval 5 seconds
OK, it's a 15 second delay but still doing nothing for 15 seconds does seem a bit excessive.
-- Chris Green
Just a guess -- and not inspired by any of the above -- is it by any chance trying to NFSmount a filesystem from a different host, not getting a response, and waiting till it times out?
Ted.
-------------------------------------------------------------------- E-Mail: (Ted Harding) Ted.Harding@manchester.ac.uk Fax-to-email: +44 (0)870 094 0861 Date: 28-Jun-10 Time: 00:26:31 ------------------------------ XFMail ------------------------------
On 28/06/10 00:26, (Ted Harding) wrote:
Just a guess -- and not inspired by any of the above -- is it by any chance trying to NFSmount a filesystem from a different host, not getting a response, and waiting till it times out?
I'd certainly hope not, given the delay is happening before the network is up :)
Chris, Why not temporarily disable ureadahead and see if that is the cause ?
That said any delay that ureadahead is generating at that point *should* be saved later on in the boot process. The whole point being that it reads everything required for a boot in one pass and caches it in memory because this should be quicker than pulling in files one by one as needed. So while this delay might vanish when you turn off ureadahead you might find that the boot takes just as long..if not longer as everything else will be loading more slowly.
Although 15 seconds seems like a long time, is / on a slowish disk ? It is normal for ureadahead to take a bit longer after there has been a major system update as there will likely be lots of files it needs to reprofile, but after that it should be making an improvement.
Another potential cause would be if something big was getting loaded at boot and it was taking ureadahead a while to get this off your disk and into memory, but for that sort of delay it would have to be pretty big. There is a guide somewhere on the ubuntu forums written by the ureadahead author to help with this sort of issue.
On Mon, Jun 28, 2010 at 09:45:35AM +0100, Wayne Stallwood wrote:
On 28/06/10 00:26, (Ted Harding) wrote:
Just a guess -- and not inspired by any of the above -- is it by any chance trying to NFSmount a filesystem from a different host, not getting a response, and waiting till it times out?
I'd certainly hope not, given the delay is happening before the network is up :)
Chris, Why not temporarily disable ureadahead and see if that is the cause ?
I might try that, yes, thanks.
That said any delay that ureadahead is generating at that point *should* be saved later on in the boot process. The whole point being that it reads everything required for a boot in one pass and caches it in memory because this should be quicker than pulling in files one by one as needed. So while this delay might vanish when you turn off ureadahead you might find that the boot takes just as long..if not longer as everything else will be loading more slowly.
Although 15 seconds seems like a long time, is / on a slowish disk ? It is normal for ureadahead to take a bit longer after there has been a major system update as there will likely be lots of files it needs to reprofile, but after that it should be making an improvement.
My feeling too was that 15 seconds is a *long* time to be reading what is actually a fast[ish] SATA disk.
Another potential cause would be if something big was getting loaded at boot and it was taking ureadahead a while to get this off your disk and into memory, but for that sort of delay it would have to be pretty big. There is a guide somewhere on the ubuntu forums written by the ureadahead author to help with this sort of issue.
Hmm, I'm just running a test (a fairly naive test) of my disks' speed by copying 5Gb (8 CD images) from on drive to the other. It's taking a *long* time, just finished - 3 minutes and 4 seconds with 17 seconds of 'sys' time. That's around 40 seconds per Gb, 25Mb per second, not scintillatingly fast. I'm unfamiliar with modern disk speeds so I'm not at all sure if that's a reasonable speed or not.
A quick Google suggests that a 25Mb second transfer rate, reading one drive and writing to another, isn't too bad at all.
On 28/06/10 11:44, Chris G wrote:
A quick Google suggests that a 25Mb second transfer rate, reading one drive and writing to another, isn't too bad at all.
25Mb a second would be terrible. However 25MB a second would be ok for what might be a non sequential read and then write back onto another disk. Modern consumer grade drives can generally manage about 100MB/s on a sequential read in optimum circumstances.
It also depends on how your SATA ports are configured in the BIOS. Legacy or non AHCI mode usually makes them fall back to master/slave emulation which means that some SATA ports will share bus bandwidth, effectively halving the access speed if you are writing two and from disks on sequential channels.
You can determine this by running multiple copies of hdparm -tT /dev/sd(x). If you are in AHCI mode then you should get pretty much the same results running it on multiple drives at the same time as when running it on a single drive. If you are in Legacy mode you may well find that the performance drops massively.
BTW in case it isn't obvious this totally kills Linux MD array performance as well so it's worth checking on any machine.
On Mon, Jun 28, 2010 at 12:09:46PM +0100, Wayne Stallwood wrote:
On 28/06/10 11:44, Chris G wrote:
A quick Google suggests that a 25Mb second transfer rate, reading one drive and writing to another, isn't too bad at all.
25Mb a second would be terrible. However 25MB a second would be ok for what might be a non sequential read and then write back onto another disk. Modern consumer grade drives can generally manage about 100MB/s on a sequential read in optimum circumstances.
It also depends on how your SATA ports are configured in the BIOS. Legacy or non AHCI mode usually makes them fall back to master/slave emulation which means that some SATA ports will share bus bandwidth, effectively halving the access speed if you are writing two and from disks on sequential channels.
You can determine this by running multiple copies of hdparm -tT /dev/sd(x). If you are in AHCI mode then you should get pretty much the same results running it on multiple drives at the same time as when running it on a single drive. If you are in Legacy mode you may well find that the performance drops massively.
BTW in case it isn't obvious this totally kills Linux MD array performance as well so it's worth checking on any machine.
Running them separately gives me:-
/dev/sda: Timing cached reads: 3490 MB in 2.00 seconds = 1745.54 MB/sec Timing buffered disk reads: 238 MB in 3.02 seconds = 78.79 MB/sec
/dev/sdb: Timing cached reads: 3298 MB in 2.00 seconds = 1649.42 MB/sec Timing buffered disk reads: 260 MB in 3.00 seconds = 86.63 MB/sec
... and running them simultaneously gives:-
/dev/sdb: Timing cached reads: 2606 MB in 2.00 seconds = 1302.25 MB/sec Timing buffered disk reads: 254 MB in 3.01 seconds = 84.36 MB/sec
/dev/sda: Timing cached reads: 2566 MB in 2.00 seconds = 1283.00 MB/sec Timing buffered disk reads: 234 MB in 3.01 seconds = 77.67 MB/sec
So simultaneous slows down the cached read a bit but has little effect on the buffered reads. Remember my 25Mb/s was an actual copy of real files from one disk drive to another, I just used 'cp' so I doubt if buffer sizes or anything were optimal.
Anyway it looks as if there's nothing fundamentally wrong with my disk read/write speeds.
On 28/06/10 12:09, Wayne Stallwood wrote:
BTW in case it isn't obvious this totally kills Linux MD array performance as well so it's worth checking on any machine.
Out of curiousity, I just tested one of my boxes with an MD array:
[root@nas ~]# hdparm -tT /dev/sda /dev/sda: Timing cached reads: 3584 MB in 2.00 seconds = 1792.19 MB/sec Timing buffered disk reads: 226 MB in 3.01 seconds = 75.04 MB/sec
[root@nas ~]# hdparm -tT /dev/sdb /dev/sdb: Timing cached reads: 3512 MB in 2.00 seconds = 1756.13 MB/sec Timing buffered disk reads: 246 MB in 3.00 seconds = 82.00 MB/sec
[root@nas ~]# hdparm -tT /dev/sda & [root@nas ~]# hdparm -tT /dev/sdb & /dev/sda: Timing cached reads: 3676 MB in 2.00 seconds = 1838.78 MB/sec Timing buffered disk reads: 240 MB in 3.02 seconds = 79.55 MB/sec /dev/sdb: Timing cached reads: 3620 MB in 2.00 seconds = 1810.69 MB/sec Timing buffered disk reads: 248 MB in 3.01 seconds = 82.30 MB/sec
(Output reformatted for readability.) That's quite a significant speed increase in cached reads when testing both together. So I re-ran the tests, and single drive tests are consistent but now I'm getting combined test results varying wildly: I just got 1277/1300 (87/83) MB/sec, then 1023/1124 (82/72), then 1236/1239 (94/91). The drives are identical Samsung models.
Should I read anything into these results?
On Sun, Jun 27, 2010 at 05:51:49PM +0100, Chris G wrote:
I have an odd situation here, after a recent reboot my system seemed *very* slow indeed, took ages to start the X desktop etc. and when I looked at the load average with 'uptime' it was over 5 which is pretty silly considering there is really nothing much happening.
While the X desktop was still thinking about appearing I ran a virtual console, logged in (even that was a bit slow) and ran tops. Tops reported virtually nothing consuming processor time.
So what's going on, why is my system slow, especially when starting, but nothing actually seems to be doing much.
This is a Core 2 Duo Quad core processor with 8Gb of memory so really should be quite quick - especially when doing nothing!
Running uptime now (40 minutes after power-up) the load average is 0.03 which is more like what I'd expect to see?
Is there any way to see what that load average is indicating?
After a couple of reboots (just as slow) it expired completely with a message about some mount entries in /etc/fstab failing. After a short panic I've managed to get things working again and, among other things, have run smartctl on my disks - nothing amiss as far as it can tell and fsck shows no errors either.
It's almost as if the system is *so* slow and overloaded at boot time that the mounts are failing. It's also complaining about the following USB entry in fstab:-
none /proc/bus/usb usbfs devgid=123,devmode=666 0 0
I've commented it out for the moment and things seem to be running a little smoother. What does it do? .... ah, it's something to do with USB in VirtualBox, I'll leave it commented out for the moment until I've sorted out my other problems.
-
Chris G -
Dennis Dryden -
Ian Thompson-Bell -
Mark Rogers -
Ted.Harding＠manchester.ac.uk -
Wayne Stallwood