Re: 2.6.x: iowait problem while burning a CD

From: Paolo Ornati
Date: Sat Feb 28 2004 - 04:15:47 EST

On Saturday 28 February 2004 01:18, Rik van Riel wrote:
> On Fri, 27 Feb 2004, Paolo Ornati wrote:
> > trying to burn a CD "on the fly" I have noticed a strange thing. During
> > the burning "iowait" remains enough low (~3%, MAX 10%) but, after a
> > little time, it suddenly and quickly goes up to 80-90%: in this
> > condition MKFS seems unable to fill the FIFO buffer as quickly as the
> > CD-writer writes
> >
> > Any ideas?
>
> At that point, mkisofs is probably running into a bazillion
> small files, in subdirectories all over the place.
>
> Because a disk seek + track read takes 10ms, it's simply not
> possible to read more than maybe 100 of these small files a
> second, so mkisofs can't keep up.

No... mkfs is reading only ONE big file ( ~ 700 MB )!

And my system shouldn't be so slow:

CPU: AMD Duron 750
RAM: 128 MB PC100
HD: 7200 RPM udma 4
File System: ResiserFS

The last time I wrote a CD I got this:

___________________________________________________________________________
System
-----------------------
K3b Version: 0.11.5
KDE Version: 3.1.4
QT Version: 3.2.1

cdrecord
-----------------------
scsidev: '/dev/hdc'
devname: '/dev/hdc'
scsibus: -2 target: -2 lun: -2
Warning: Open by 'devname' is unintentional and not supported.
Linux sg driver version: 3.5.27
Cdrecord 2.00.3 (i686-pc-linux-gnu) Copyright (C) 1995-2002 Jörg Schilling
TOC Type: 1 = CD-ROM
Using libscg version 'schily-0.7'
Driveropts: 'burnfree'
atapi: 1
Device type : Removable CD-ROM
Version : 0
Response Format: 2
Capabilities :
Vendor_info : 'HL-DT-ST'
Identifikation : 'CD-RW GCE-8400B '
Revision : '1.03'
Device seems to be: Generic mmc CD-RW.
Using generic SCSI-3/mmc CD-R driver (mmc_cdr).
Driver flags : MMC-2 SWABAUDIO BURNFREE
Supported modes: TAO PACKET SAO SAO/R96P SAO/R96R RAW/R16 RAW/R96P RAW/R96R
Drive buf size : 1962752 = 1916 KB
FIFO size : 4194304 = 4096 KB
Track 01: data 700 MB
Total size: 804 MB (79:41.01) = 358576 sectors
Lout start: 804 MB (79:43/01) = 358576 sectors
Current Secsize: 2048
ATIP info from disk:
Indicated writing power: 4
Is not unrestricted
Is not erasable
Disk sub type: Medium Type A, high Beta category (A+) (3)
ATIP start of lead in: -11849 (97:24/01)
ATIP start of lead out: 359847 (79:59/72)
Disk type: Long strategy type (Cyanine, AZO or similar)
Manuf. index: 25
Manufacturer: Taiyo Yuden Company Limited
Blocks total: 359847 Blocks current: 359847 Blocks remaining: 1271
Starting to write CD/DVD at speed 32 in real SAO mode for single session.
Last chance to quit, starting real write in 2 seconds.
1 seconds.
0 seconds. Operation starts.
Waiting for reader process to fill input buffer ... input buffer ready.
BURN-Free is OFF.
Turning BURN-Free on
Performing OPC...
Sending CUE sheet...
/usr/bin/cdrecord: WARNING: Drive returns wrong startsec (0) using -150
Writing pregap for track 1 at -150
Starting new track at sector: 0
Track 01: 0 of 700 MB written.
Track 01: 1 of 700 MB written (fifo 96%) [buf 98%] 2.4x.
Track 01: 2 of 700 MB written (fifo 100%) [buf 99%] 0.8x.
Track 01: 3 of 700 MB written (fifo 100%) [buf 99%] 20.8x.
Track 01: 4 of 700 MB written (fifo 100%) [buf 99%] 20.2x.
Track 01: 5 of 700 MB written (fifo 98%) [buf 99%] 20.9x.
Track 01: 6 of 700 MB written (fifo 100%) [buf 99%] 20.2x.
Track 01: 7 of 700 MB written (fifo 100%) [buf 99%] 21.0x.
Track 01: 8 of 700 MB written (fifo 100%) [buf 99%] 20.4x.
Track 01: 9 of 700 MB written (fifo 100%) [buf 99%] 21.0x.
Track 01: 10 of 700 MB written (fifo 100%) [buf 99%] 20.4x.
Track 01: 11 of 700 MB written (fifo 98%) [buf 99%] 21.1x.
Track 01: 12 of 700 MB written (fifo 100%) [buf 99%] 20.5x.
Track 01: 13 of 700 MB written (fifo 100%) [buf 99%] 21.2x.
Track 01: 14 of 700 MB written (fifo 100%) [buf 99%] 20.6x.
Track 01: 15 of 700 MB written (fifo 100%) [buf 99%] 21.3x.
Track 01: 16 of 700 MB written (fifo 100%) [buf 99%] 20.7x.
Track 01: 17 of 700 MB written (fifo 100%) [buf 99%] 21.4x.
Track 01: 18 of 700 MB written (fifo 98%) [buf 99%] 20.8x.
Track 01: 19 of 700 MB written (fifo 100%) [buf 99%] 21.5x.
Track 01: 20 of 700 MB written (fifo 100%) [buf 99%] 20.8x.
Track 01: 21 of 700 MB written (fifo 100%) [buf 99%] 3.7x.
Track 01: 22 of 700 MB written (fifo 100%) [buf 99%] 16.2x.

[....] OK

Track 01: 169 of 700 MB written (fifo 96%) [buf 99%] 16.3x. <---- ;-(
Track 01: 170 of 700 MB written (fifo 79%) [buf 99%] 16.8x.
Track 01: 171 of 700 MB written (fifo 65%) [buf 99%] 16.3x.
Track 01: 172 of 700 MB written (fifo 50%) [buf 99%] 16.8x.
Track 01: 173 of 700 MB written (fifo 26%) [buf 99%] 16.2x.
Track 01: 174 of 700 MB written (fifo 17%) [buf 99%] 16.7x.
Track 01: 175 of 700 MB written (fifo 4%) [buf 99%] 16.2x.
Track 01: 176 of 700 MB written (fifo 1%) [buf 35%] 7.4x.
Track 01: 177 of 700 MB written (fifo 1%) [buf 82%] 7.9x.
Track 01: 178 of 700 MB written (fifo 14%) [buf 99%] 6.2x.
Track 01: 179 of 700 MB written (fifo 1%) [buf 95%] 14.8x.
Track 01: 180 of 700 MB written (fifo 1%) [buf 56%] 9.5x.
Track 01: 181 of 700 MB written (fifo 4%) [buf 69%] 7.2x.
Track 01: 182 of 700 MB written (fifo 31%) [buf 99%] 6.1x.
Track 01: 183 of 700 MB written (fifo 32%) [buf 99%] 16.1x.
Track 01: 184 of 700 MB written (fifo 31%) [buf 99%] 16.6x.
Track 01: 185 of 700 MB written (fifo 32%) [buf 99%] 16.0x.
Track 01: 186 of 700 MB written (fifo 31%) [buf 99%] 16.5x.
Track 01: 187 of 700 MB written (fifo 26%) [buf 99%] 16.0x.
Track 01: 188 of 700 MB written (fifo 29%) [buf 99%] 16.5x.
Track 01: 189 of 700 MB written (fifo 26%) [buf 99%] 17.0x.
Track 01: 190 of 700 MB written (fifo 23%) [buf 99%] 16.4x.
Track 01: 191 of 700 MB written (fifo 23%) [buf 99%] 17.0x.
Track 01: 192 of 700 MB written (fifo 26%) [buf 99%] 16.4x.
Track 01: 193 of 700 MB written (fifo 31%) [buf 99%] 16.9x.
Track 01: 194 of 700 MB written (fifo 26%) [buf 99%] 16.4x.
Track 01: 195 of 700 MB written (fifo 31%) [buf 99%] 16.9x.
Track 01: 196 of 700 MB written (fifo 29%) [buf 99%] 16.3x.
Track 01: 197 of 700 MB written (fifo 28%) [buf 99%] 16.9x.
Track 01: 198 of 700 MB written (fifo 23%) [buf 99%] 16.3x.
Track 01: 199 of 700 MB written (fifo 23%) [buf 99%] 16.8x.
Track 01: 200 of 700 MB written (fifo 23%) [buf 99%] 16.3x.
Track 01: 201 of 700 MB written (fifo 20%) [buf 99%] 16.8x.
Track 01: 202 of 700 MB written (fifo 17%) [buf 99%] 16.3x.
Track 01: 203 of 700 MB written (fifo 14%) [buf 99%] 16.8x.
Track 01: 204 of 700 MB written (fifo 14%) [buf 99%] 16.2x.
Track 01: 205 of 700 MB written (fifo 7%) [buf 99%] 16.7x.
Track 01: 206 of 700 MB written (fifo 1%) [buf 99%] 16.2x.
Track 01: 207 of 700 MB written (fifo 7%) [buf 70%] 10.7x.
Track 01: 208 of 700 MB written (fifo 1%) [buf 75%] 17.7x.
Track 01: 209 of 700 MB written (fifo 4%) [buf 57%] 12.3x.
Track 01: 210 of 700 MB written (fifo 1%) [buf 51%] 14.7x.
Track 01: 211 of 700 MB written (fifo 4%) [buf 40%] 12.2x.
Track 01: 212 of 700 MB written (fifo 46%) [buf 93%] 6.1x.
Track 01: 213 of 700 MB written (fifo 40%) [buf 99%] 19.0x.
Track 01: 214 of 700 MB written (fifo 40%) [buf 99%] 16.1x.
Track 01: 215 of 700 MB written (fifo 37%) [buf 99%] 16.6x.
Track 01: 216 of 700 MB written (fifo 32%) [buf 99%] 16.0x.
Track 01: 217 of 700 MB written (fifo 31%) [buf 99%] 16.5x.
Track 01: 218 of 700 MB written (fifo 29%) [buf 99%] 16.0x.
Track 01: 219 of 700 MB written (fifo 26%) [buf 99%] 16.5x.
Track 01: 220 of 700 MB written (fifo 23%) [buf 99%] 17.0x.
Track 01: 221 of 700 MB written (fifo 23%) [buf 99%] 16.4x.
Track 01: 222 of 700 MB written (fifo 37%) [buf 99%] 16.9x.
Track 01: 223 of 700 MB written (fifo 62%) [buf 99%] 16.4x.
Track 01: 224 of 700 MB written (fifo 68%) [buf 99%] 16.9x.
Track 01: 225 of 700 MB written (fifo 75%) [buf 99%] 16.4x.
Track 01: 226 of 700 MB written (fifo 82%) [buf 99%] 16.9x.
Track 01: 227 of 700 MB written (fifo 90%) [buf 99%] 16.3x.
Track 01: 228 of 700 MB written (fifo 95%) [buf 99%] 16.9x.
Track 01: 229 of 700 MB written (fifo 100%) [buf 99%] 16.3x.

[....] OK

Track 01: 314 of 700 MB written (fifo 96%) [buf 99%] 16.4x.. <---- ;-(
Track 01: 315 of 700 MB written (fifo 95%) [buf 99%] 17.0x.
Track 01: 316 of 700 MB written (fifo 93%) [buf 99%] 16.4x.
Track 01: 317 of 700 MB written (fifo 92%) [buf 99%] 16.9x.
Track 01: 318 of 700 MB written (fifo 87%) [buf 99%] 16.4x.
Track 01: 319 of 700 MB written (fifo 82%) [buf 99%] 16.9x.
Track 01: 320 of 700 MB written (fifo 78%) [buf 99%] 16.3x.
Track 01: 321 of 700 MB written (fifo 71%) [buf 99%] 16.9x.
Track 01: 322 of 700 MB written (fifo 71%) [buf 99%] 16.3x.
Track 01: 323 of 700 MB written (fifo 62%) [buf 99%] 16.8x.
Track 01: 324 of 700 MB written (fifo 59%) [buf 99%] 16.3x.
Track 01: 325 of 700 MB written (fifo 46%) [buf 99%] 16.8x.
Track 01: 326 of 700 MB written (fifo 32%) [buf 99%] 16.3x.
Track 01: 327 of 700 MB written (fifo 25%) [buf 99%] 16.8x.
Track 01: 328 of 700 MB written (fifo 10%) [buf 99%] 16.2x.
Track 01: 329 of 700 MB written (fifo 10%) [buf 99%] 16.7x.
Track 01: 330 of 700 MB written (fifo 26%) [buf 99%] 16.2x.
Track 01: 331 of 700 MB written (fifo 40%) [buf 99%] 16.7x.
Track 01: 332 of 700 MB written (fifo 53%) [buf 99%] 16.2x.
Track 01: 333 of 700 MB written (fifo 65%) [buf 99%] 16.7x.
Track 01: 334 of 700 MB written (fifo 78%) [buf 99%] 16.1x.
Track 01: 335 of 700 MB written (fifo 98%) [buf 99%] 16.6x.
Track 01: 336 of 700 MB written (fifo 100%) [buf 99%] 16.1x.

[...] OK

Track 01: 343 of 700 MB written (fifo 90%) [buf 99%] 16.5x.. <---- ;-(
Track 01: 344 of 700 MB written (fifo 78%) [buf 99%] 17.0x.
Track 01: 345 of 700 MB written (fifo 65%) [buf 99%] 16.4x.
Track 01: 346 of 700 MB written (fifo 56%) [buf 99%] 17.0x.
Track 01: 347 of 700 MB written (fifo 42%) [buf 99%] 16.4x.
Track 01: 348 of 700 MB written (fifo 31%) [buf 99%] 16.9x.
Track 01: 349 of 700 MB written (fifo 17%) [buf 99%] 16.4x.
Track 01: 350 of 700 MB written (fifo 4%) [buf 99%] 16.9x.
Track 01: 351 of 700 MB written (fifo 4%) [buf 48%] 8.4x.
Track 01: 352 of 700 MB written (fifo 4%) [buf 60%] 8.6x.
Track 01: 353 of 700 MB written (fifo 20%) [buf 99%] 6.3x.
Track 01: 354 of 700 MB written (fifo 10%) [buf 99%] 16.8x.
Track 01: 355 of 700 MB written (fifo 4%) [buf 99%] 16.3x.
Track 01: 356 of 700 MB written (fifo 1%) [buf 81%] 12.3x.
Track 01: 357 of 700 MB written (fifo 1%) [buf 55%] 11.0x.
Track 01: 358 of 700 MB written (fifo 1%) [buf 79%] 10.7x.
Track 01: 359 of 700 MB written (fifo 20%) [buf 99%] 6.1x.
Track 01: 360 of 700 MB written (fifo 17%) [buf 99%] 16.7x.
Track 01: 361 of 700 MB written (fifo 7%) [buf 99%] 16.2x.
Track 01: 362 of 700 MB written (fifo 1%) [buf 99%] 16.7x.
Track 01: 363 of 700 MB written (fifo 4%) [buf 84%] 12.6x.
Track 01: 364 of 700 MB written (fifo 1%) [buf 45%] 9.5x.
Track 01: 365 of 700 MB written (fifo 1%) [buf 69%] 10.8x.
Track 01: 366 of 700 MB written (fifo 28%) [buf 99%] 5.8x.
Track 01: 367 of 700 MB written (fifo 26%) [buf 99%] 16.1x.
Track 01: 368 of 700 MB written (fifo 25%) [buf 99%] 16.6x.
Track 01: 369 of 700 MB written (fifo 29%) [buf 99%] 16.1x.
Track 01: 370 of 700 MB written (fifo 31%) [buf 99%] 16.6x.
Track 01: 371 of 700 MB written (fifo 29%) [buf 99%] 16.0x.
Track 01: 372 of 700 MB written (fifo 25%) [buf 99%] 16.5x.
Track 01: 373 of 700 MB written (fifo 32%) [buf 99%] 16.0x.
Track 01: 374 of 700 MB written (fifo 26%) [buf 99%] 16.5x.
Track 01: 375 of 700 MB written (fifo 40%) [buf 99%] 17.0x.
Track 01: 376 of 700 MB written (fifo 48%) [buf 99%] 16.4x.
Track 01: 377 of 700 MB written (fifo 56%) [buf 99%] 16.9x.
Track 01: 378 of 700 MB written (fifo 71%) [buf 99%] 16.4x.
Track 01: 379 of 700 MB written (fifo 78%) [buf 99%] 16.9x.
Track 01: 380 of 700 MB written (fifo 87%) [buf 99%] 16.4x.
Track 01: 381 of 700 MB written (fifo 98%) [buf 99%] 16.9x.
Track 01: 382 of 700 MB written (fifo 100%) [buf 99%] 16.3x.

[...] OK

Track 01: 437 of 700 MB written (fifo 98%) [buf 99%] 17.0x.. <---- ;-(
Track 01: 438 of 700 MB written (fifo 96%) [buf 99%] 16.4x.
Track 01: 439 of 700 MB written (fifo 85%) [buf 99%] 17.0x.
Track 01: 440 of 700 MB written (fifo 90%) [buf 99%] 16.4x.
Track 01: 441 of 700 MB written (fifo 78%) [buf 99%] 16.9x.
Track 01: 442 of 700 MB written (fifo 78%) [buf 99%] 16.4x.
Track 01: 443 of 700 MB written (fifo 71%) [buf 99%] 16.9x.
Track 01: 444 of 700 MB written (fifo 68%) [buf 99%] 16.4x.
Track 01: 445 of 700 MB written (fifo 62%) [buf 99%] 16.8x.
Track 01: 446 of 700 MB written (fifo 53%) [buf 99%] 16.3x.
Track 01: 447 of 700 MB written (fifo 50%) [buf 99%] 16.8x.
Track 01: 448 of 700 MB written (fifo 42%) [buf 99%] 16.3x.
Track 01: 449 of 700 MB written (fifo 40%) [buf 99%] 16.8x.
Track 01: 450 of 700 MB written (fifo 45%) [buf 99%] 16.2x.
Track 01: 451 of 700 MB written (fifo 51%) [buf 99%] 16.7x.
Track 01: 452 of 700 MB written (fifo 65%) [buf 99%] 16.2x.
Track 01: 453 of 700 MB written (fifo 76%) [buf 99%] 16.7x.
Track 01: 454 of 700 MB written (fifo 90%) [buf 99%] 16.2x.
Track 01: 455 of 700 MB written (fifo 100%) [buf 99%] 16.7x.

[....] OK

Track 01: 490 of 700 MB written (fifo 98%) [buf 99%] 16.6x.. <---- ;-(
Track 01: 491 of 700 MB written (fifo 98%) [buf 99%] 16.1x.
Track 01: 492 of 700 MB written (fifo 98%) [buf 99%] 16.6x.
Track 01: 493 of 700 MB written (fifo 95%) [buf 99%] 16.1x.
Track 01: 494 of 700 MB written (fifo 89%) [buf 99%] 16.6x.
Track 01: 495 of 700 MB written (fifo 84%) [buf 99%] 16.0x.
Track 01: 496 of 700 MB written (fifo 81%) [buf 99%] 16.5x.
Track 01: 497 of 700 MB written (fifo 71%) [buf 99%] 16.0x.
Track 01: 498 of 700 MB written (fifo 71%) [buf 99%] 16.5x.
Track 01: 499 of 700 MB written (fifo 62%) [buf 99%] 17.0x.
Track 01: 500 of 700 MB written (fifo 59%) [buf 99%] 16.4x.
Track 01: 501 of 700 MB written (fifo 53%) [buf 99%] 16.9x.
Track 01: 502 of 700 MB written (fifo 48%) [buf 99%] 16.4x.
Track 01: 503 of 700 MB written (fifo 46%) [buf 99%] 16.9x.
Track 01: 504 of 700 MB written (fifo 48%) [buf 99%] 16.4x.
Track 01: 505 of 700 MB written (fifo 50%) [buf 99%] 16.9x.
Track 01: 506 of 700 MB written (fifo 45%) [buf 99%] 16.4x.
Track 01: 507 of 700 MB written (fifo 43%) [buf 99%] 16.9x.
Track 01: 508 of 700 MB written (fifo 39%) [buf 99%] 16.3x.
Track 01: 509 of 700 MB written (fifo 37%) [buf 99%] 16.8x.
Track 01: 510 of 700 MB written (fifo 32%) [buf 99%] 16.3x.
Track 01: 511 of 700 MB written (fifo 31%) [buf 99%] 16.8x.
Track 01: 512 of 700 MB written (fifo 26%) [buf 99%] 16.3x.
Track 01: 513 of 700 MB written (fifo 28%) [buf 99%] 16.8x.
Track 01: 514 of 700 MB written (fifo 26%) [buf 99%] 16.2x.
Track 01: 515 of 700 MB written (fifo 31%) [buf 99%] 16.7x.
Track 01: 516 of 700 MB written (fifo 32%) [buf 99%] 16.2x.
Track 01: 517 of 700 MB written (fifo 31%) [buf 99%] 16.7x.
Track 01: 518 of 700 MB written (fifo 29%) [buf 99%] 16.2x.
Track 01: 519 of 700 MB written (fifo 28%) [buf 99%] 16.7x.
Track 01: 520 of 700 MB written (fifo 23%) [buf 99%] 16.1x.
Track 01: 521 of 700 MB written (fifo 28%) [buf 99%] 16.6x.
Track 01: 522 of 700 MB written (fifo 29%) [buf 99%] 16.1x.
Track 01: 523 of 700 MB written (fifo 34%) [buf 99%] 16.6x.
Track 01: 524 of 700 MB written (fifo 40%) [buf 99%] 16.1x.
Track 01: 525 of 700 MB written (fifo 43%) [buf 99%] 16.6x.
Track 01: 526 of 700 MB written (fifo 46%) [buf 99%] 16.0x.
Track 01: 527 of 700 MB written (fifo 50%) [buf 99%] 16.5x.
Track 01: 528 of 700 MB written (fifo 59%) [buf 99%] 16.0x.
Track 01: 529 of 700 MB written (fifo 71%) [buf 99%] 16.5x.
Track 01: 530 of 700 MB written (fifo 81%) [buf 99%] 17.0x.
Track 01: 531 of 700 MB written (fifo 93%) [buf 99%] 16.4x.

[.......................]

Writing time: 327.622s
Average write speed 14.8x.
Min drive buffer fill was 35%
Fixating...
Fixating time: 11.906s
/usr/bin/cdrecord: fifo had 11567 puts and 11567 gets.
/usr/bin/cdrecord: fifo was 320 times empty and 5909 times full, min fill
was 0%.
BURN-Free was 11 times used.
___________________________________________________________________________


FULL LOG is attached.
As I have already said, every time the buffer goes down I see iowait go up
to high values (70%, 80%, 90%).

All it works well if I make the ISO image before the writing process.

Bye

--
Paolo Ornati
Linux v2.6.3

Attachment: burning.txt.gz
Description: GNU Zip compressed data