When I copy a file(13Megs) from /home/ to /tmp/, sync takes almost 2 minutes. When I copy the same file to /usr/local/, sync returns almost right away. Both filesystems are ext3 and are on the same harddrive. When sync is running, the harddrive light stays on but I don't hear it doing anything. dmesg doesn't show any errors either. Below is the `time` output for each command. If you need anymore information let me know.. The CPU is a PIII866 with 512MB RAM. $ uname -a Linux dev-01 2.4.19-pre10-ac2 #3 Sun Jun 30 18:56:04 EDT 2002 i686 unknown $ hdparm /dev/hda /dev/hda: multcount = 16 (on) I/O support = 1 (32-bit) unmaskirq = 1 (on) using_dma = 1 (on) keepsettings = 0 (off) nowerr = 0 (off) readonly = 0 (off) readahead = 8 (on) geometry = 1868/255/63, sectors = 30015216, start = 0 busstate = 1 (on) $ cat /proc/mounts /dev/hda1 / ext3 rw,noatime 0 0 /dev/hda2 /home ext3 rw,noatime 0 0 /dev/hda3 /usr ext3 rw,noatime 0 0 $ df -h Filesystem Size Used Avail Use% Mounted on /dev/hda1 387M 162M 205M 45% / /dev/hda2 3.4G 2.1G 1.1G 65% /home /dev/hda3 10G 6.3G 3.4G 65% /usr $ cat /proc/ide/via ----------VIA BusMastering IDE Configuration---------------- Driver Version: 3.34 South Bridge: VIA vt82c686b Revision: ISA 0x40 IDE 0x6 Highest DMA rate: UDMA100 BM-DMA base: 0xc000 PCI clock: 33.3MHz Master Read Cycle IRDY: 0ws Master Write Cycle IRDY: 0ws BM IDE Status Register Read Retry: yes Max DRDY Pulse Width: No limit -----------------------Primary IDE-------Secondary IDE------ Read DMA FIFO flush: yes yes End Sector FIFO flush: no no Prefetch Buffer: no no Post Write Buffer: no no Enabled: yes yes Simplex only: no no Cable Type: 80w 40w -------------------drive0----drive1----drive2----drive3----- Transfer Mode: UDMA PIO PIO PIO Address Setup: 30ns 120ns 30ns 120ns Cmd Active: 90ns 90ns 90ns 90ns Cmd Recovery: 30ns 30ns 30ns 30ns Data Active: 90ns 330ns 90ns 330ns Data Recovery: 30ns 270ns 30ns 270ns Cycle Time: 30ns 600ns 120ns 600ns Transfer Rate: 66.6MB/s 3.3MB/s 16.6MB/s 3.3MB/s $ ls -al mozilla-i686-pc-linux-gnu-sea.tar.gz -rw-rw-r-- 1 khromy khromy 13M Jul 2 07:42 mozilla-i686-pc-linux-gnu-sea.tar.gz * time output when I copy to /usr/local $ time cp mozilla-i686-pc-linux-gnu-sea.tar.gz /usr/local/ 0.00user 0.19system 0:00.18elapsed 102%CPU (0avgtext+0avgdata 0maxresident)k $ time sync 0.00user 0.00system 0:00.00elapsed 0%CPU (0avgtext+0avgdata 0maxresident)k $ time rm /usr/local/mozilla-i686-pc-linux-gnu-sea.tar.gz 0.00user 0.00system 0:00.00elapsed 0%CPU (0avgtext+0avgdata 0maxresident)k * time output when I copy to /tmp $ time cp mozilla-i686-pc-linux-gnu-sea.tar.gz /tmp/ 0.01user 0.24system 0:00.25elapsed 98%CPU (0avgtext+0avgdata 0maxresident)k $ time sync 0.00user 0.05system 1:39.14elapsed 0%CPU (0avgtext+0avgdata 0maxresident)k $ time rm /tmp/mozilla-i686-pc-linux-gnu-sea.tar.gz 0.00user 0.05system 0:00.05elapsed 98%CPU (0avgtext+0avgdata 0maxresident)k -- L1: khromy ;khromy(at)lnuxlab.ath.cx
Below is the `vmstat 1` output while sync is running after copying the file to /tmp/. procs memory swap io system cpu r b w swpd free buff cache si so bi bo in cs us sy id 1 1 1 0 71128 86792 190688 0 0 5 4 110 274 3 1 95 1 1 1 0 71064 86792 190692 0 0 0 0 225 320 0 2 98 0 1 1 0 71064 86792 190692 0 0 0 249 222 302 0 0 100 1 1 1 0 71064 86792 190692 0 0 0 0 221 292 0 0 100 1 1 2 0 71060 86792 190692 0 0 0 253 223 304 0 1 99 2 1 2 0 71060 86792 190692 0 0 0 0 223 296 0 0 100 0 1 2 0 71060 86792 190692 0 0 0 257 222 302 0 1 99 1 1 2 0 71060 86792 190692 0 0 0 0 221 290 0 0 100 1 1 2 0 71060 86792 190692 0 0 0 248 226 320 0 4 96 0 1 2 0 71060 86792 190692 0 0 0 0 233 324 1 0 99 1 1 2 0 71060 86792 190692 0 0 0 248 224 329 0 1 99 1 1 2 0 71060 86792 190692 0 0 0 0 220 299 0 1 99 1 1 2 0 71060 86792 190692 0 0 0 250 223 314 0 1 99 1 1 3 0 71060 86792 190692 0 0 0 0 221 307 0 1 99 1 1 2 0 71060 86792 190692 0 0 0 250 222 320 0 0 100 0 1 2 0 71060 86792 190692 0 0 0 0 221 291 0 0 100 2 1 2 0 71060 86792 190692 0 0 0 249 230 306 0 1 99 1 1 2 0 71060 86792 190692 0 0 0 0 220 303 0 1 99 1 1 2 0 71060 86792 190692 0 0 0 249 224 317 0 0 100 0 1 3 0 71060 86792 190692 0 0 0 59 221 300 0 0 100 2 1 3 0 71060 86792 190692 0 0 0 249 230 302 0 2 98 1 1 3 0 71060 86792 190692 0 0 0 0 221 314 0 0 100 1 1 3 0 71060 86792 190692 0 0 0 0 223 330 0 0 100 1 1 3 0 71060 86792 190692 0 0 0 271 222 304 0 1 99 1 1 3 0 71060 86792 190692 0 0 0 0 222 315 0 0 100 0 1 3 0 71060 86792 190692 0 0 0 249 220 305 0 0 100 2 1 3 0 71060 86792 190692 0 0 0 0 223 295 0 0 100 0 1 3 0 71060 86792 190692 0 0 0 252 229 306 0 0 100 1 1 3 0 71060 86792 190692 0 0 0 0 241 302 0 0 100 0 1 3 0 71060 86792 190692 0 0 0 249 288 490 0 1 99 0 1 3 0 71060 86792 190692 0 0 0 0 316 3453 49 5 47 2 1 3 0 71060 86792 190692 0 0 0 249 282 439 0 1 99 1 1 3 0 71060 86792 190692 0 0 0 0 272 407 0 2 98 1 1 3 0 71056 86792 190692 0 0 0 258 308 3808 35 13 52 1 1 3 0 71052 86792 190692 0 0 0 0 326 1893 18 2 80 1 1 3 0 71052 86792 190692 0 0 0 249 318 916 7 4 89 0 1 3 0 71052 86792 190692 0 0 0 0 276 435 0 0 100 1 1 3 0 71052 86792 190692 0 0 0 259 273 441 0 0 100 1 1 3 0 71060 86792 190692 0 0 0 0 223 878 8 0 92 0 1 3 0 71056 86792 190692 0 0 0 249 295 481 0 1 99 1 1 3 0 71056 86792 190692 0 0 0 0 229 291 0 0 100 1 1 3 0 71056 86792 190692 0 0 0 249 225 290 0 0 100 2 1 3 0 71056 86792 190692 0 0 0 0 229 291 0 1 99 0 1 3 0 71056 86792 190692 0 0 0 249 229 285 0 0 100 1 1 3 0 71056 86792 190692 0 0 0 0 223 289 0 0 100 0 1 3 0 71056 86792 190692 0 0 0 249 221 282 0 0 100 1 1 3 0 71052 86792 190696 0 0 0 0 230 280 0 0 100 0 1 3 0 71052 86792 190696 0 0 0 272 226 300 0 1 99 2 1 3 0 71052 86792 190696 0 0 0 0 233 315 0 0 100 1 1 3 0 71052 86792 190696 0 0 0 429 222 304 0 1 99 1 1 3 0 71048 86792 190696 0 0 0 0 240 273 0 0 100 2 1 3 0 71048 86792 190696 0 0 0 252 222 294 0 0 100 1 1 3 0 71048 86792 190696 0 0 0 0 222 279 0 3 97 0 1 3 0 71048 86792 190696 0 0 0 248 223 290 0 1 99 1 1 3 0 71048 86792 190696 0 0 0 0 229 280 0 2 98 0 1 3 0 71048 86792 190696 0 0 0 250 221 284 0 2 98 1 1 3 0 71048 86792 190696 0 0 0 0 221 284 0 3 97 0 1 3 0 71048 86792 190696 0 0 0 249 221 283 0 0 100 1 1 3 0 71048 86792 190696 0 0 0 0 225 286 0 0 100 0 1 3 0 71048 86792 190696 0 0 0 281 232 302 0 2 98 1 1 3 0 71048 86792 190696 0 0 0 0 273 335 5 1 94 1 1 3 0 71048 86792 190696 0 0 0 249 245 305 1 0 99 1 1 3 0 71048 86792 190696 0 0 0 0 224 307 1 1 98 1 1 3 0 71044 86792 190696 0 0 0 249 224 300 0 0 100 1 1 3 0 71044 86792 190696 0 0 0 0 223 288 0 3 97 0 1 3 0 71044 86792 190696 0 0 0 249 229 291 0 2 98 1 1 3 0 71044 86792 190696 0 0 0 0 224 290 0 1 99 0 1 3 0 71044 86792 190696 0 0 0 249 220 286 0 1 99 1 1 3 0 71044 86792 190696 0 0 0 0 224 292 1 1 98 0 1 3 0 71044 86792 190696 0 0 0 287 221 300 0 1 99 1 1 3 0 71044 86792 190696 0 0 0 0 223 286 0 0 100 2 1 3 0 71044 86792 190696 0 0 0 249 231 287 0 1 99 1 1 3 0 71044 86792 190696 0 0 0 0 221 277 0 0 100 0 1 3 0 71044 86792 190696 0 0 0 249 227 296 0 0 100 1 1 3 0 71044 86792 190696 0 0 0 0 221 273 0 0 100 0 1 3 0 71044 86792 190696 0 0 0 249 221 290 0 1 99 1 1 3 0 71044 86792 190696 0 0 0 0 221 274 0 0 100 0 1 3 0 71044 86792 190696 0 0 0 249 220 283 0 1 99 1 1 3 0 71044 86792 190696 0 0 0 0 223 295 0 0 100 0 1 3 0 71044 86792 190696 0 0 0 249 222 285 0 1 99 1 1 3 0 71044 86792 190696 0 0 0 0 220 276 0 0 100 1 1 3 0 71044 86792 190696 0 0 0 249 221 284 0 3 97 1 1 3 0 71044 86792 190696 0 0 0 0 221 274 0 0 100 0 1 3 0 71044 86792 190696 0 0 0 249 228 297 0 1 99 2 1 3 0 71044 86792 190696 0 0 0 0 220 273 0 0 100 0 1 3 0 71044 86792 190696 0 0 0 249 234 309 0 0 100 1 1 3 0 71044 86792 190696 0 0 0 0 221 281 0 1 99 0 1 3 0 71044 86792 190696 0 0 0 275 221 285 0 1 99 1 1 3 0 71044 86792 190696 0 0 0 0 222 275 0 0 100 0 1 2 0 71044 86792 190696 0 0 0 20 237 310 0 1 99 <sync finally returns around here> 2 0 2 0 71044 86792 190696 0 0 0 4 236 455 0 0 100 2 0 0 0 71116 86800 190696 0 0 0 99 207 497 0 0 100 1 0 0 0 71116 86800 190696 0 0 0 0 101 279 0 0 100 0 0 0 0 71112 86800 190700 0 0 0 0 105 301 0 0 100 2 0 0 0 71112 86800 190700 0 0 0 110 171 282 0 0 100 0 0 0 0 71112 86800 190700 0 0 0 0 101 282 0 0 100 1 0 0 0 71112 86800 190700 0 0 0 0 103 289 0 0 100 0 0 0 0 71112 86800 190700 0 0 0 0 101 277 0 0 100 1 0 0 0 71112 86800 190700 0 0 0 0 101 273 0 0 100 0 0 0 0 71112 86800 190700 0 0 0 16 104 289 0 0 100 2 0 0 0 71112 86800 190700 0 0 0 0 103 290 0 0 100 1 0 0 0 71112 86800 190700 0 0 0 0 103 289 0 0 100 -- L1: khromy ;khromy(at)lnuxlab.ath.cx
khromy wrote:> > When I copy a file(13Megs) from /home/ to /tmp/, sync takes almost 2 minutes. > When I copy the same file to /usr/local/, sync returns almost right away.Gad. Please, mount those filesystems as ext2 and retest. -
On Tue, Jul 02, 2002 at 08:24:54PM -0700, Andrew Morton wrote:>khromy wrote: >> >>When I copy a file(13Megs) from /home/ to /tmp/, sync takes almost 2 minutes. >>When I copy the same file to /usr/local/, sync returns almost right away. > >Gad. Please, mount those filesystems as ext2 and retest.I just did, same exact behavior.. Anything else? -- L1: khromy ;khromy(at)lnuxlab.ath.cx
khromy wrote:> > On Tue, Jul 02, 2002 at 08:24:54PM -0700, Andrew Morton wrote: > >khromy wrote: > >> > >>When I copy a file(13Megs) from /home/ to /tmp/, sync takes almost 2 minutes. > >>When I copy the same file to /usr/local/, sync returns almost right away. > > > >Gad. Please, mount those filesystems as ext2 and retest. > > I just did, same exact behavior.. Anything else? >Possibly what is happening is that the /tmp partition lies on a part of the disk which has a higher platter transfer speed and this higher speed is causing retries or other problems further down the chain. You could have a fiddle with hdparm, try slowing down the interface speed. Try a different set of cables, too. -
On Wed, Jul 03, 2002 at 08:25:45AM -0200, Denis Vlasenko wrote:> On 3 July 2002 00:20, khromy wrote: > > When I copy a file(13Megs) from /home/ to /tmp/, sync takes almost 2 > > minutes. When I copy the same file to /usr/local/, sync returns almost > > right away. Both filesystems are ext3 and are on the same harddrive. When > > sync is running, the harddrive light stays on but I don't hear it doing > > anything. dmesg doesn't show any errors either. Below is the `time` output > > for each command. If you need anymore information let me know.. > > Can be useful: > * strace -r sync > * ksymoopsed SysRq-T output (sync part only)*** strace -r sync 0.000000 execve("/bin/sync", ["sync"], [/* 24 vars */]) = 0 0.000260 uname({sys="Linux", node="dev-01", ...}) = 0 0.000361 brk(0) = 0x804a308 0.000067 old_mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x40014000 0.000105 open("/etc/ld.so.preload", O_RDONLY) = -1 ENOENT (No such file or directory) 0.000108 open("/etc/ld.so.cache", O_RDONLY) = 3 0.000064 fstat64(3, {st_mode=S_IFREG|0644, st_size=24001, ...}) = 0 0.000111 old_mmap(NULL, 24001, PROT_READ, MAP_PRIVATE, 3, 0) = 0x40015000 0.000068 close(3) = 0 0.000065 open("/lib/libc.so.6", O_RDONLY) = 3 0.000086 read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\24\222"..., 1024) = 1024 0.000120 fstat64(3, {st_mode=S_IFREG|0755, st_size=1149584, ...}) = 0 0.000087 old_mmap(NULL, 1162080, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) = 0x4001b000 0.000068 mprotect(0x4012d000, 39776, PROT_NONE) = 0 0.000056 old_mmap(0x4012d000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED, 3, 0x112000) = 0x4012d000 0.000098 old_mmap(0x40133000, 15200, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x40133000 0.000072 close(3) = 0 0.000786 munmap(0x40015000, 24001) = 0 0.000176 brk(0) = 0x804a308 0.000049 brk(0x804a330) = 0x804a330 0.000051 brk(0x804b000) = 0x804b000 0.000092 sync() = 0 92.243322 _exit(0) = ? *** ksymoopsed SysRq-T sync D 00200034 0 1200 1199 (NOTLB) Using defaults from ksymoops -t elf32-i386 -a i386 Call Trace: [<c01ae4d7>] [<c01ae688>] [<c01aeb40>] [<c01af13a>] [<c01af1f9>] [<c014344c>] [<c0143566>] [<c01435bb>] [<c014370a>] [<c01438a7>] [<c014394f>] [<c01091c3>] Proc; sync>>EIP; 00200034 Before first symbol <====Trace; c01ae4d7 <__get_request_wait+e7/f0> Trace; c01ae688 <account_io_start+38/60> Trace; c01aeb40 <__make_request+1c0/6c0> Trace; c01af13a <generic_make_request+fa/160> Trace; c01af1f9 <submit_bh+59/80> Trace; c014344c <write_locked_buffers+2c/40> Trace; c0143566 <write_some_buffers+106/130> Trace; c01435bb <write_unlocked_buffers+2b/40> Trace; c014370a <sync_buffers+1a/70> Trace; c01438a7 <fsync_dev+27/b0> Trace; c014394f <sys_sync+f/20> Trace; c01091c3 <tracesys+1f/23> -- L1: khromy ;khromy(at)lnuxlab.ath.cx
Hi, On Tue, Jul 02, 2002 at 10:20:51PM -0400, khromy wrote:> When I copy a file(13Megs) from /home/ to /tmp/, sync takes almost 2 minutes. > When I copy the same file to /usr/local/, sync returns almost right away. Both > filesystems are ext3 and are on the same harddrive. When sync is running, > the harddrive light stays on but I don't hear it doing anything. dmesg doesn't > show any errors either. Below is the `time` output for each command. If you > need anymore information let me know..Ugh. My first guess would be that you have one enormously fragmented filesystem. 13MB in 2 minutes? A modern disk should get that amount of data to disk in one second, but massive fragmentation can simply kill disk performance. If /home is on the same disk, do you get the same problem trying to write there? --Stephen
On Wed, Jul 03, 2002 at 10:22:44AM +0100, Stephen C. Tweedie wrote:> Ugh. My first guess would be that you have one enormously fragmented > filesystem. 13MB in 2 minutes? A modern disk should get that amount > of data to disk in one second, but massive fragmentation can simply > kill disk performance.I just ran fsck and found out that hda1(where /tmp/ is on) is 5.1% non-contiguous. Is that enough for the slowdown? Below is df -h. Filesystem Size Used Avail Use% Mounted on /dev/hda1 387M 156M 212M 43% / /dev/hda2 3.4G 2.1G 1.1G 65% /home /dev/hda3 10G 6.4G 3.3G 66% /usr -- L1: khromy ;khromy(at)lnuxlab.ath.cx
On 3 July 2002 00:20, khromy wrote:> When I copy a file(13Megs) from /home/ to /tmp/, sync takes almost 2 > minutes. When I copy the same file to /usr/local/, sync returns almost > right away. Both filesystems are ext3 and are on the same harddrive. When > sync is running, the harddrive light stays on but I don't hear it doing > anything. dmesg doesn't show any errors either. Below is the `time` output > for each command. If you need anymore information let me know..Can be useful: * strace -r sync * ksymoopsed SysRq-T output (sync part only) -- vda
On Wed, Jul 03, 2002 at 11:56:46AM -0400, Mark Hahn wrote:> ugh, this is very old, back in the 10G/platter days. > considering that 60G/platter ship now, and all new disks > are 30-40G/platter. > > out of curiosity, what does hdparm say about the low-level speed > of this disk?* hdparm -Tt /dev/hda /dev/hda: Timing buffer-cache reads: 128 MB in 0.73 seconds =175.34 MB/sec Timing buffered disk reads: 64 MB in 2.22 seconds = 28.83 MB/sec * hdparm /dev/hda /dev/hda: multcount = 16 (on) I/O support = 1 (32-bit) unmaskirq = 1 (on) using_dma = 1 (on) keepsettings = 0 (off) nowerr = 0 (off) readonly = 0 (off) readahead = 8 (on) geometry = 1868/255/63, sectors = 30015216, start = 0 busstate = 1 (on) * hdparm -i /dev/hda /dev/hda: Model=Maxtor 51536U3, FwRev=DA6207V0, SerialNo=K304R35C Config={ Fixed } RawCHS=16383/16/63, TrkSize=0, SectSize=0, ECCbytes=57 BuffType=DualPortCache, BuffSize=2048kB, MaxMultSect=16, MultSect=16 CurCHS=16383/16/63, CurSects=16514064, LBA=yes, LBAsects=30015216 IORDY=on/off, tPIO={min:120,w/IORDY:120}, tDMA={min:120,rec:120} PIO modes: pio0 pio1 pio2 pio3 pio4 DMA modes: mdma0 mdma1 mdma2 udma0 udma1 udma2 udma3 *udma4 AdvancedPM=yes: disabled (255) WriteCache=enabled Drive Supports : ATA/ATAPI-4 T13 1153D revision 17 : ATA-1 ATA-2 ATA-3 ATA-4 ATA-5 -- L1: khromy ;khromy(at)lnuxlab.ath.cx
> > When I copy a file(13Megs) from /home/ to /tmp/, sync takes almost 2 minutes. > > When I copy the same file to /usr/local/, sync returns almost right away. > > Gad. Please, mount those filesystems as ext2 and retest.Checking out $(smartctl -l /dev/hda) might be advisable too. T.
On Wed, Jul 03, 2002 at 07:43:40PM +0200, Tomas Szepe wrote:> Checking out $(smartctl -l /dev/hda) might be advisable too.# smartctl -l /dev/hda SMART Error Log: SMART Error Logging Version: 1 Error Log Data Structure Pointer: 05 ATA Error Count: 1038 Non-Fatal Count: 0 Error Log Structure 1: DCR FR SC SN CL SH D/H CR Timestamp 08 00 02 71 01 01 e0 c8 54770 08 00 02 75 01 01 e0 c8 54770 08 00 02 79 01 01 e0 c8 54770 08 d0 01 00 4f c2 e0 b0 54770 08 d1 01 01 4f c2 e0 b0 54770 00 04 01 0b 4f c2 e0 51 1608563 Error Log Structure 2: DCR FR SC SN CL SH D/H CR Timestamp 08 00 0a 03 51 00 e0 ca 54728 08 00 0a 9b 6b 00 e0 ca 54728 08 00 14 cd 0c 00 e0 ca 54728 08 00 02 e1 0c 00 e0 ca 54728 08 d0 01 00 4f c2 e0 b0 54729 00 04 01 0b 4f c2 e0 51 1608522 Error Log Structure 3: DCR FR SC SN CL SH D/H CR Timestamp 08 00 02 4b 00 07 e0 ca 54812 08 00 02 5d 00 07 e0 ca 54812 08 00 02 4f 02 07 e0 ca 54812 08 00 04 41 00 00 e0 ca 54812 08 00 01 01 00 00 a0 a1 54823 00 04 01 01 00 00 a0 51 1608551 Error Log Structure 4: DCR FR SC SN CL SH D/H CR Timestamp 08 00 02 4b 00 07 e0 ca 54812 08 00 02 5d 00 07 e0 ca 54812 08 00 02 4f 02 07 e0 ca 54812 08 00 04 41 00 00 e0 ca 54812 08 00 05 01 00 00 a0 a1 54867 00 04 05 01 00 00 a0 51 1608529 Error Log Structure 5: DCR FR SC SN CL SH D/H CR Timestamp 08 d2 00 01 4f c2 a0 b0 54867 08 00 01 01 00 00 a0 c4 54867 08 03 0c 01 00 00 a0 ef 54867 08 03 44 01 00 00 a0 ef 54867 08 03 44 01 00 00 a0 22 54867 00 04 44 01 00 00 a0 51 1608529 -- L1: khromy ;khromy(at)lnuxlab.ath.cx