PROMBLEM: CD burning at 16x uses excessive CPU, although DMA is enabled

[1.] One line summary of the problem:
CD burning at 16x uses excessive CPU, although DMA is enabled

[2.] Full description of the problem/report:
My system seems to use a lot of CPU time when writing CDs at 16x. The system is unable to feed the burning software's buffer fast enough when burning software (cdrecord 1.11a20, cdrdao 1.1.5) is run as normal user. If run as root, system is almost unresponsive during the burn.

This concerns only audio and raw data burns, burning of ISO images goes fine with very little load. 12x and 8x burns are also fine, although using serial ports is error prone while even a 8x burn is going on. CD Writer is LG GCE-8160B, secondary master, alone in the cable. CD writer and HD has DMA enabled, by default writer uses mdma2. Other modes have been tried, but no change. Disabling DMA does not help.

This problem does not happen in FreeBSD 4.5-STABLE with cdrecord 1.11a20.

[3.] Keywords (i.e., modules, networking, kernel):
CD writing, ATAPI, SG

[4.] Kernel version (from /proc/version):
2.4.18, 2.4.16, 2.2.19, 2.4.19pre6

[7.] Environment
[7.1.] Software (add the output of the ver_linux script here) Linux dorkstar 2.4.18 #2 Wed Apr 3 22:03:26 EEST 2002 i686 unknown

Gnu C                  2.95.4
Gnu make               3.79.1
util-linux             2.11n
mount                  2.11n
modutils               2.4.13
e2fsprogs              1.26
Linux C Library        2.2.5
Dynamic linker (ldd)   2.2.5
Procps                 2.0.7
Net-tools              1.60
Kbd                    command
Sh-utils               2.0.11
Modules Loaded         sg cmpci soundcore ncr53c8xx isofs via686a i2c-proc i2c-isa i2c-core autofs4 lirc_serial ip_conntrack_ftp ipt_REJECT ipt_limit ipt_LOG ipt_state ip_conntrack iptable_filter ip_tables 3c59x ide-scsi sr_mod cdrom rtc nls_iso8859-1 nls_cp437 vfat fat

[7.2.] Processor information (from /proc/cpuinfo):
processor : 0
vendor_id : AuthenticAMD
cpu family : 6
model : 3
model name : AMD Duron(tm) processor
stepping : 1
cpu MHz : 799.649
cache size : 64 KB
fdiv_bug : no
hlt_bug : no
f00f_bug : no
coma_bug : no
fpu : yes
fpu_exception : yes
cpuid level : 1
wp : yes
flags : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 mmx fxsr syscall mmxext 3dnowext 3dnow
bogomips : 1595.80

[7.3.] Module information (from /proc/modules):

sg                     25124   0 (autoclean)
cmpci                  25380   0 (autoclean)
soundcore               3652   2 (autoclean) [cmpci]
ncr53c8xx              53184   0
isofs                  18016   0 (autoclean)
via686a                 8036   0 (unused)
i2c-proc                6144   0 [via686a]
i2c-isa                 1188   0 (unused)
i2c-core               13128   0 [via686a i2c-proc i2c-isa]
autofs4                 8644   2 (autoclean)
lirc_serial             7520   0
ip_conntrack_ftp        3424   0 (unused)
ipt_REJECT              2976   1 (autoclean)
ipt_limit                928   3 (autoclean)
ipt_LOG                 3200  13 (autoclean)
ipt_state                576   2 (autoclean)
ip_conntrack           13548   2 (autoclean) [ip_conntrack_ftp ipt_state]
iptable_filter          1760   1 (autoclean)
ip_tables              10944   5 [ipt_REJECT ipt_limit ipt_LOG ipt_state iptable_filter]
3c59x                  25608   1 (autoclean)
ide-scsi                7712   0 (autoclean)
sr_mod                 13624   0 (autoclean)
cdrom                  28512   0 (autoclean) [sr_mod]
rtc                     5656   0 (autoclean)
nls_iso8859-1           2848   2 (autoclean)
nls_cp437               4384   2 (autoclean)
vfat                    9916   2 (autoclean)
fat                    31576   0 (autoclean) [vfat]

[7.4.] Loaded driver and hardware information (/proc/ioports, /proc/iomem) /proc/ioports :
0000-001f : dma1
0020-003f : pic1
0040-005f : timer
0060-006f : keyboard
0070-007f : rtc
0080-008f : dma page reg
00a0-00bf : pic2
00c0-00df : dma2
00f0-00ff : fpu
0170-0177 : ide1
01f0-01f7 : ide0
0376-0376 : ide1
03c0-03df : vga+
03f6-03f6 : ide0
03f8-03ff : lirc_serial
0cf8-0cff : PCI conf1
5000-500f : VIA Technologies, Inc. VT82C686 [Apollo Super ACPI] 6000-607f : VIA Technologies, Inc. VT82C686 [Apollo Super ACPI]
6000-607f : via686a-sensors
c000-c00f : VIA Technologies, Inc. Bus Master IDE
c000-c007 : ide0
c008-c00f : ide1
c400-c41f : VIA Technologies, Inc. UHCI USB
c800-c81f : VIA Technologies, Inc. UHCI USB (#2)
cc00-ccff : ATI Technologies Inc 3D Rage Pro 215GP
d000-d07f : 3Com Corporation 3c905C-TX [Fast Etherlink]
d000-d07f : 00:09.0
d400-d4ff : LSI Logic / Symbios Logic (formerly NCR) 53c810
d400-d47f : ncr53c8xx
d800-d8ff : C-Media Electronics Inc CM8738
d800-d8ff : cmpci
dc00-dc07 : Promise Technology, Inc. 20265
dc00-dc07 : ide2
e000-e003 : Promise Technology, Inc. 20265
e002-e002 : ide2
e400-e407 : Promise Technology, Inc. 20265
e800-e803 : Promise Technology, Inc. 20265
ec00-ec3f : Promise Technology, Inc. 20265
ec00-ec07 : ide2
ec08-ec0f : ide3
ec10-ec3f : PDC20265

/proc/iomem:
00000000-0009fbff : System RAM
0009fc00-0009ffff : reserved
000a0000-000bffff : Video RAM area
000c0000-000c7fff : Video ROM
000f0000-000fffff : System ROM
00100000-0ffeffff : System RAM
00100000-001fe615 : Kernel code
001fe616-0024a0b7 : Kernel data
0fff0000-0fff2fff : ACPI Non-volatile Storage 0fff3000-0fffffff : ACPI Tables
d0000000-d7ffffff : PCI Bus #01
d0000000-d7ffffff : nVidia Corporation NV11 (GeForce2 MX)
d8000000-dbffffff : VIA Technologies, Inc. VT8363/8365 [KT133/KM133] dc000000-ddffffff : PCI Bus #01
dc000000-dcffffff : nVidia Corporation NV11 (GeForce2 MX)
de000000-deffffff : ATI Technologies Inc 3D Rage Pro 215GP e0000000-e001ffff : Promise Technology, Inc. 20265 e0020000-e002007f : 3Com Corporation 3c905C-TX [Fast Etherlink] e0021000-e00210ff : LSI Logic / Symbios Logic (formerly NCR) 53c810 e0022000-e0022fff : ATI Technologies Inc 3D Rage Pro 215GP ffff0000-ffffffff : reserved

[7.5.] PCI information ('lspci -vvv' as root)
00:00.0 Host bridge: VIA Technologies, Inc. VT8363/8365 [KT133/KM133] (rev 03)
Control: I/O- Mem+ BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR- FastB2B-
Status: Cap+ 66Mhz- UDF- FastB2B- ParErr- DEVSEL=medium >TAbort- <TAbort- <MAbort+ >SERR- <PERR+
Latency: 0
Region 0: Memory at d8000000 (32-bit, prefetchable) [size=64M]
Capabilities: [a0] AGP version 2.0
Status: RQ=31 SBA+ 64bit- FW- Rate=x1,x2
Command: RQ=0 SBA- AGP- 64bit- FW- Rate=<none>
Capabilities: [c0] Power Management version 2
Flags: PMEClk- DSI- D1- D2- AuxCurrent=0mA PME(D0-,D1-,D2-,D3hot-,D3cold-)
Status: D0 PME-Enable- DSel=0 DScale=0 PME-

00:01.0 PCI bridge: VIA Technologies, Inc. VT8363/8365 [KT133/KM133 AGP] (prog-if 00 [Normal decode])
Control: I/O+ Mem+ BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR- FastB2B-
Status: Cap+ 66Mhz+ UDF- FastB2B- ParErr- DEVSEL=medium >TAbort- <TAbort- <MAbort+ >SERR- <PERR-
Latency: 0
Bus: primary=00, secondary=01, subordinate=01, sec-latency=0
I/O behind bridge: 0000f000-00000fff
Memory behind bridge: dc000000-ddffffff
Prefetchable memory behind bridge: d0000000-d7ffffff
BridgeCtl: Parity- SERR- NoISA+ VGA+ MAbort- >Reset- FastB2B-
Capabilities: [80] Power Management version 2
Flags: PMEClk- DSI- D1+ D2- AuxCurrent=0mA PME(D0-,D1-,D2-,D3hot-,D3cold-)
Status: D0 PME-Enable- DSel=0 DScale=0 PME-

00:07.0 ISA bridge: VIA Technologies, Inc. VT82C686 [Apollo Super South] (rev 40)
Subsystem: VIA Technologies, Inc. VT82C686/A PCI to ISA Bridge
Control: I/O+ Mem+ BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr- Stepping+ SERR- FastB2B-
Status: Cap+ 66Mhz- UDF- FastB2B- ParErr- DEVSEL=medium >TAbort- <TAbort- <MAbort- >SERR- <PERR-
Latency: 0
Capabilities: [c0] Power Management version 2
Flags: PMEClk- DSI- D1- D2- AuxCurrent=0mA PME(D0-,D1-,D2-,D3hot-,D3cold-)
Status: D0 PME-Enable- DSel=0 DScale=0 PME-

00:07.1 IDE interface: VIA Technologies, Inc. Bus Master IDE (rev 06) (prog-if 8a [Master SecP PriP])
Control: I/O+ Mem+ BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR- FastB2B-
Status: Cap+ 66Mhz- UDF- FastB2B+ ParErr- DEVSEL=medium >TAbort- <TAbort- <MAbort- >SERR- <PERR-
Latency: 32
Region 4: I/O ports at c000 [size=16]
Capabilities: [c0] Power Management version 2
Flags: PMEClk- DSI- D1- D2- AuxCurrent=0mA PME(D0-,D1-,D2-,D3hot-,D3cold-)
Status: D0 PME-Enable- DSel=0 DScale=0 PME-

00:07.2 USB Controller: VIA Technologies, Inc. UHCI USB (rev 16) (prog-if 00 [UHCI])
Subsystem: Unknown device 0925:1234
Control: I/O+ Mem+ BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR- FastB2B-
Status: Cap+ 66Mhz- UDF- FastB2B- ParErr- DEVSEL=medium >TAbort- <TAbort- <MAbort- >SERR- <PERR-
Latency: 32, cache line size 08
Interrupt: pin D routed to IRQ 5
Region 4: I/O ports at c400 [size=32]
Capabilities: [80] Power Management version 2
Flags: PMEClk- DSI- D1- D2- AuxCurrent=0mA PME(D0-,D1-,D2-,D3hot-,D3cold-)
Status: D0 PME-Enable- DSel=0 DScale=0 PME-

00:07.3 USB Controller: VIA Technologies, Inc. UHCI USB (rev 16) (prog-if 00 [UHCI])
Subsystem: Unknown device 0925:1234
Control: I/O+ Mem+ BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR- FastB2B-
Status: Cap+ 66Mhz- UDF- FastB2B- ParErr- DEVSEL=medium >TAbort- <TAbort- <MAbort- >SERR- <PERR-
Latency: 32, cache line size 08
Interrupt: pin D routed to IRQ 5
Region 4: I/O ports at c800 [size=32]
Capabilities: [80] Power Management version 2
Flags: PMEClk- DSI- D1- D2- AuxCurrent=0mA PME(D0-,D1-,D2-,D3hot-,D3cold-)
Status: D0 PME-Enable- DSel=0 DScale=0 PME-

00:07.4 Host bridge: VIA Technologies, Inc. VT82C686 [Apollo Super ACPI] (rev 40)
Control: I/O- Mem- BusMaster- SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR- FastB2B-
Status: Cap+ 66Mhz- UDF- FastB2B+ ParErr- DEVSEL=medium >TAbort- <TAbort- <MAbort- >SERR- <PERR-
Interrupt: pin ? routed to IRQ 9
Capabilities: [68] Power Management version 2
Flags: PMEClk- DSI- D1- D2- AuxCurrent=0mA PME(D0-,D1-,D2-,D3hot-,D3cold-)
Status: D0 PME-Enable- DSel=0 DScale=0 PME-

00:08.0 VGA compatible controller: ATI Technologies Inc 3D Rage Pro 215GP (rev 5c) (prog-if 00 [VGA])
Subsystem: ATI Technologies Inc: Unknown device 0000
Control: I/O- Mem- BusMaster- SpecCycle- MemWINV- VGASnoop- ParErr- Stepping+ SERR- FastB2B-
Status: Cap- 66Mhz- UDF- FastB2B+ ParErr- DEVSEL=medium >TAbort- <TAbort- <MAbort- >SERR- <PERR- Region 0: Memory at de000000 (32-bit, prefetchable) [disabled] [size=16M] Region 1: I/O ports at cc00 [disabled] [size=256]
Region 2: Memory at e0022000 (32-bit, non-prefetchable) [disabled] [size=4K] Expansion ROM at <unassigned> [disabled] [size=128K]

00:09.0 Ethernet controller: 3Com Corporation 3c905C-TX [Fast Etherlink] (rev 74)
Subsystem: 3Com Corporation 3C905C-TX Fast Etherlink for PC Management NIC
Control: I/O+ Mem+ BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR- FastB2B-
Status: Cap+ 66Mhz- UDF- FastB2B- ParErr- DEVSEL=medium >TAbort- <TAbort- <MAbort- >SERR- <PERR-
Latency: 32 (2500ns min, 2500ns max), cache line size 08
Interrupt: pin A routed to IRQ 10
Region 0: I/O ports at d000 [size=128]
Region 1: Memory at e0020000 (32-bit, non-prefetchable) [size=128]
Expansion ROM at <unassigned> [disabled] [size=128K]
Capabilities: [dc] Power Management version 2
Flags: PMEClk- DSI- D1+ D2+ AuxCurrent=0mA PME(D0+,D1+,D2+,D3hot+,D3cold+)
Status: D0 PME-Enable- DSel=0 DScale=2 PME-

00:0a.0 SCSI storage controller: LSI Logic / Symbios Logic (formerly NCR) 53c810 (rev 02)
Control: I/O+ Mem+ BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR- FastB2B-
Status: Cap- 66Mhz- UDF- FastB2B- ParErr- DEVSEL=medium >TAbort- <TAbort- <MAbort- >SERR- <PERR-
Latency: 32
Interrupt: pin A routed to IRQ 11
Region 0: I/O ports at d400 [size=256]
Region 1: Memory at e0021000 (32-bit, non-prefetchable) [size=256]

00:0d.0 Multimedia audio controller: C-Media Electronics Inc CM8738 (rev 10)
Subsystem: C-Media Electronics Inc CMI8738/C3DX PCI Audio Device
Control: I/O+ Mem- BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR- FastB2B-
Status: Cap+ 66Mhz- UDF- FastB2B- ParErr- DEVSEL=medium >TAbort- <TAbort- <MAbort- >SERR- <PERR-
Latency: 32 (500ns min, 6000ns max)
Interrupt: pin A routed to IRQ 10
Region 0: I/O ports at d800 [size=256]
Capabilities: [c0] Power Management version 2
Flags: PMEClk- DSI- D1+ D2+ AuxCurrent=0mA PME(D0-,D1-,D2-,D3hot-,D3cold-)
Status: D0 PME-Enable- DSel=0 DScale=0 PME-

00:0f.0 RAID bus controller: Promise Technology, Inc. 20265 (rev 02)
Subsystem: Promise Technology, Inc.: Unknown device 4d33
Control: I/O+ Mem+ BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR- FastB2B-
Status: Cap+ 66Mhz- UDF- FastB2B- ParErr- DEVSEL=medium >TAbort- <TAbort- <MAbort- >SERR- <PERR-
Latency: 32
Interrupt: pin A routed to IRQ 10
Region 0: I/O ports at dc00 [size=8]
Region 1: I/O ports at e000 [size=4]
Region 2: I/O ports at e400 [size=8]
Region 3: I/O ports at e800 [size=4]
Region 4: I/O ports at ec00 [size=64]
Region 5: Memory at e0000000 (32-bit, non-prefetchable) [size=128K]
Expansion ROM at <unassigned> [disabled] [size=64K]
Capabilities: [58] Power Management version 1
Flags: PMEClk- DSI- D1- D2- AuxCurrent=0mA PME(D0-,D1-,D2-,D3hot-,D3cold-)
Status: D0 PME-Enable- DSel=0 DScale=0 PME-

01:00.0 VGA compatible controller: nVidia Corporation NV11 (GeForce2 MX) (rev a1) (prog-if 00 [VGA])
Subsystem: Elsa AG: Unknown device 0c60
Control: I/O+ Mem+ BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR- FastB2B-
Status: Cap+ 66Mhz+ UDF- FastB2B+ ParErr- DEVSEL=medium >TAbort- <TAbort- <MAbort- >SERR- <PERR-
Latency: 32 (1250ns min, 250ns max)
Interrupt: pin A routed to IRQ 5
Region 0: Memory at dc000000 (32-bit, non-prefetchable) [size=16M]
Region 1: Memory at d0000000 (32-bit, prefetchable) [size=128M]
Expansion ROM at <unassigned> [disabled] [size=64K]
Capabilities: [60] Power Management version 2
Flags: PMEClk- DSI- D1- D2- AuxCurrent=0mA PME(D0-,D1-,D2-,D3hot-,D3cold-)
Status: D0 PME-Enable- DSel=0 DScale=0 PME-
Capabilities: [44] AGP version 2.0
Status: RQ=31 SBA- 64bit- FW+ Rate=x1,x2
Command: RQ=0 SBA- AGP- 64bit- FW- Rate=<none>

[7.6.] SCSI information (from /proc/scsi/scsi) Attached devices:
Host: scsi0 Channel: 00 Id: 00 Lun: 00
Vendor: HL-DT-ST Model: CD-RW GCE-8160B Rev: 2.01
Type: CD-ROM ANSI SCSI revision: 02
Host: scsi1 Channel: 00 Id: 00 Lun: 00
Vendor: NEC Model: CD-ROM DRIVE:462 Rev: 1.16
Type: CD-ROM ANSI SCSI revision: 02
Host: scsi1 Channel: 00 Id: 02 Lun: 00
Vendor: RICOH Model: CD-R/RW MP7060S Rev: 1.70
Type: CD-ROM ANSI SCSI revision: 02

That's a hint things are not working as you expect...

With all the information you provided, you have totally not quatified
how much CPU you find "excessive." I would not be surprised to see 10-15% of the CPU, virtually all in system time, as a normal burn of an ISO image. If the time is in user mode with other image types, it may well be that you are doing something which actually requires a lot of CPU (byte swapping or some such).

Going from a disk to a CD using DMA on both should not take much
*system* CPU, even if these are ATAPI (assuming they are not on the same cable).

bill davidsen <[email protected]>
  CTO, TMR Associates, Inc
Doing interesting things with little computers since 1979.

I'm not completely sure about burning audio, but linux doesn't read audio cds using DMA. It just wont on ide devices. You can use a patch that allows this from andrew morton. I dont write many audio cds so I've never tested it's effect on writing a cd, only reading. I imagine it's not safe to use dma on raw/audio cds. but go check it out anyways.

I've seen the patch, but the OP was posting about burning CDs. My
recollection is that even audio CDs don't use much CPU with DMA, but there might be lots of options and stuff involved. I've asked for a breakdown of CPU use so we can see if it's user or system, how much, etc.

bill davidsen <[email protected]>
  CTO, TMR Associates, Inc
Doing interesting things with little computers since 1979.

I didn't think this is relevant, except if I were trying to copy a CD on the fly, but that's not the case. But I have now tried it, no change. In fact, what I tried was this linux-2.4.19-pre5-jam2 patch collection which includes that and low latency and O(1) scheduler patches, among other things. Didn't seem to help, however.

I didn't really know how to put it. Maybe system load would be better. But the actual problem is, I effectively can't burn audio and other types at 16x in Linux, while there is no problem in some other operating systems with the same hardware and applications.

Here're some time figures from cdrdao:

cdrdao simulate -n --speed 8 foo.cue 2.62s user 3.37s system 1% cpu 6:41.86 total cdrdao simulate -n --speed 12 foo.cue 2.78s user 29.91s system 12% cpu 4:31.71 total cdrdao simulate -n --speed 16 foo.cue 2.67s user 128.77s system 52% cpu 4:10.68 total

So yes, system time goes up quite steeply.

But even though 50% is quite high, CPU load is not the problem as such, the problem is getting data to the writer fast enough. And it's not happening. Even a single audio track that is completely cached so that there is no HD access has problems. It's like somehow accessing the CD writer hogs the system for such long periods that there is insufficient time to fill the writing program's buffer.

One thing I noticed just now. If I turn off unmaskirq for the CD writer with hdparm -u 0 /dev/hdc, it helps a little, but not enough. Time reports now:

cdrdao simulate -n --speed 16 foo.cue 2.75s user 75.18s system 58% cpu 2:13.22 total

Okay, this is good information. At the risk of asking a dumb question,
are you sure that both the burner and the source drive ar using DMA? And that they are on separate cables (controllers)? Usually the high system time indicated either PIO in use or some path looping in the kernel.

That's still high. My only fast burners are in the office, if I get back
during the week I'll run a test at 16 and 24x and see what I find.

This would be a good question for the CD writing list,
[email protected].

bill davidsen <[email protected]>
  CTO, TMR Associates, Inc
Doing interesting things with little computers since 1979.

I'm fairly certain. I can read that test image at ~37MB/s and 35% CPU, which can't be PIO. The CD writer reads at ~3.7MB/s and 3% CPU usage.

Yes. Two HDs, one writer, all on different channels. The other HD is on the motherboards Promise 20265 "raid" controller.

I tried that some time ago. So far, this is a sort of repetition of that. Joerg Schilling suggested that maybe I don't have DMA on or the reader and writer are on the same cable. Other discussion was off topic...

In fact, I've also had this conversation from the other point of view with someone else, who was asking about this same problem in the finnish Linux group, sfnet.atk.linux. Now I have the same LG CD writer, the same VIA KT133A chipset, the same problem and the same discussion... I'd be amused if the problem weren't still unresolved.

I decided to post here after I tried FreeBSD, didn't have a problem and thus it seemed likely that this is a Linux specific problem.

I think I'll try to put together another system and see what happens there. I wonder if SGI's kernprof thing would be useful with this. I'll try that too, when I have the time.

Hi,

I tested with my computer - the CD-R:s that I had limited the testing to 10x. But when testing that it indicated 33% CPU in system, but not accouted to any process by top.

I have done some profiling with my kernel 2.4.17-rmap12f
I think this indicates that the time spent for this kernel is IRQ happening during idle time - correct?

I am not sure that this is the same situation that Anssi has but 33% are quite a lot (more than he got, DMAs are enabled). But at least it is another comparative datapoint...

/RogerL

--- output from readprofile (>=3) ------------------

     3 __aux_write_ack                            0.0938
     3 kmalloc                                    0.0115
     3 pipe_poll                                  0.0300
     3 sys_select                                 0.0026
     4 add_wait_queue                             0.1000
     4 link_path_walk                             0.0021
     4 rest_init                                  0.1000
     4 rmqueue                                    0.0059
     4 tasklet_action                             0.0303
     4 timer_bh                                   0.0066
     5 __free_pages_ok                            0.0068
     5 sock_poll                                  0.1250
     6 __rdtsc_delay                              0.2143
     6 __switch_to                                0.0326
     6 __wake_up                                  0.0375
     6 kfree                                      0.0405
     7 fget                                       0.1750
     7 poll_freewait                              0.1029
     7 sys_write                                  0.0357
     8 unix_poll                                  0.0541
     9 schedule                                   0.0110
    11 do_softirq                                 0.0671
    12 do_anonymous_page                          0.0517
    12 do_select                                  0.0252
    23 handle_IRQ_event                           0.2614
    24 file_read_actor                            0.1765

5960 ide_intr 17.7381
36056 default_idle 901.4000
42283 total 0.0418

Roger Larsson
Skellefteå
Sweden

Here it is:

With unmaskirq=1 first:

     3 block_read_full_page                       0.0059
     3 fget                                       0.0625
     3 get_unused_buffer_head                     0.0234
     3 kmalloc                                    0.0134
     3 kmem_cache_free                            0.0187
     4 __free_pages_ok                            0.0081
     4 ext3_get_branch                            0.0147
     4 get_hash_table                             0.0278
     4 journal_try_to_free_buffers                0.0278
     4 rmqueue                                    0.0093
     4 scsi_old_done                              0.0027
     5 generic_make_request                       0.0164
     5 try_to_free_buffers                        0.0223
     6 ext3_releasepage                           0.1250
     6 sys_read                                   0.0268
     6 system_call                                0.1071
     7 __rdtsc_delay                              0.2188
     7 apm_bios_call                              0.0547
     7 scsi_request_fn                            0.0093
     8 __make_request                             0.0050
     8 ide_wait_stat                              0.0294
     8 schedule                                   0.0091
     9 ide_dmaproc                                0.0161
     9 start_request                              0.0148
    13 do_generic_file_read                       0.0123
    14 ide_end_request                            0.0972
    22 do_rw_disk                                 0.0229
    49 handle_IRQ_event                           0.5104
   239 file_read_actor                            2.4896

3324 default_idle 69.2500
20097 ide_output_data 104.6719
23952 total 0.0236
Number of interrupts on ide1 during burn: 17531

And then, unmaskirq=0:

     3 __free_pages                               0.0938
     3 ext3_get_branch                            0.0110
     3 fget                                       0.0625
     3 kmem_cache_reap                            0.0069
     3 page_cache_read                            0.0156
     3 scsi_block_when_processing_errors          0.0144
     3 shrink_cache                               0.0042
     4 __make_request                             0.0025
     4 __rdtsc_delay                              0.1250
     4 __switch_to                                0.0208
     4 ext3_get_block_handle                      0.0058
     4 fput                                       0.0179
     4 get_unused_buffer_head                     0.0312
     4 ide_dma_intr                               0.0208
     4 ide_dmaproc                                0.0071
     4 ide_output_data                            0.0208
     4 kfree                                      0.0250
     4 kmem_cache_free                            0.0250
     4 rmqueue                                    0.0093
     4 sys_read                                   0.0179
     4 try_to_free_buffers                        0.0179
     6 ext3_releasepage                           0.1250
     6 generic_file_readahead                     0.0179
     6 timer_bh                                   0.0099
     7 scsi_old_done                              0.0048
     8 start_request                              0.0132
     8 system_call                                0.1429
     9 ide_wait_stat                              0.0331
    10 do_generic_file_read                       0.0095
    10 ide_end_request                            0.0694
    10 schedule                                   0.0114
    11 do_rw_disk                                 0.0115
    15 apm_bios_call                              0.1172
   168 do_softirq                                 0.9545
   234 file_read_actor                            2.4375
  1942 handle_IRQ_event                          20.2292
  2949 default_idle                              61.4375
  6808 ide_intr                                  18.5000

12333 total 0.0122
Number of interrupts on ide1 during burn: 17532

Strace -c with unmaskirq=1:

execve("/usr/local/bin/cdrdao", ["cdrdao", "simulate", "-n", "--speed", "16", "f oo.cue"], [/* 34 vars */]) = 0
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------

 95.66    2.141856         244      8767           ioctl
  2.16    0.048346           3     17516           gettimeofday
  1.08    0.024089          45       534           write
  0.51    0.011371           2      5826           rt_sigprocmask
  0.43    0.009593         564        17         5 open
  0.10    0.002251         225        10         1 read
  0.03    0.000694         174         4           munmap
  0.01    0.000314           1       314           nanosleep
  0.01    0.000122           7        18           old_mmap
  0.00    0.000055           5        12           close
  0.00    0.000053           5        10           brk
  0.00    0.000041          21         2         2 rt_sigsuspend
  0.00    0.000033           2        16           rt_sigaction
  0.00    0.000029          29         1           pipe
  0.00    0.000028           3        11           fstat64
  0.00    0.000024           5         5           mprotect
  0.00    0.000021          21         1           clone
  0.00    0.000010          10         1           wait4
  0.00    0.000010           5         2         2 sigreturn
  0.00    0.000008           4         2           uname
  0.00    0.000008           8         1           _sysctl
  0.00    0.000008           3         3           fcntl64
  0.00    0.000003           3         1         1 munlockall
  0.00    0.000003           2         2           geteuid32
  0.00    0.000002           2         1           getpid
  0.00    0.000002           2         1           setrlimit
  0.00    0.000002           2         1           getrlimit

------ ----------- ----------- --------- --------- ----------------
100.00 2.238976 33079 11 total

and with unmaskirq=0:
execve("/usr/local/bin/cdrdao", ["cdrdao", "simulate", "-n", "--speed", "16", "f oo.cue"], [/* 34 vars */]) = 0
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------

 99.75   35.801229        4084      8767           ioctl
  0.14    0.051375           3     17516           gettimeofday
  0.07    0.024269          45       534           write
  0.03    0.011883           2      5826           rt_sigprocmask
  0.00    0.000709         177         4           munmap
  0.00    0.000267          18        15         3 open
  0.00    0.000263           1       263           nanosleep
  0.00    0.000117           7        18           old_mmap
  0.00    0.000083           8        10         1 read
  0.00    0.000057          29         2         2 rt_sigsuspend
  0.00    0.000056           5        12           close
  0.00    0.000048           5        10           brk
  0.00    0.000036           2        16           rt_sigaction
  0.00    0.000029          29         1           pipe
  0.00    0.000028           3        11           fstat64
  0.00    0.000026           5         5           mprotect
  0.00    0.000020          20         1           clone
  0.00    0.000010           5         2         2 sigreturn
  0.00    0.000009           9         1           wait4
  0.00    0.000008           4         2           uname
  0.00    0.000008           8         1           _sysctl
  0.00    0.000007           2         3           fcntl64
  0.00    0.000003           3         1           setrlimit
  0.00    0.000003           3         1         1 munlockall
  0.00    0.000003           3         1           getrlimit
  0.00    0.000003           2         2           geteuid32
  0.00    0.000002           2         1           getpid

------ ----------- ----------- --------- --------- ----------------
100.00 35.890551 33026 9 total

AMD Duron 800MHz. Of course it's a problem but not the main problem here.

How would I get that?

I think the fact that it works with FreeBSD should have been enough to show that 'excessive' doesn't need to be qualified.

The question is, how is CD burning of raw data different from CD burning of ISO images, in respect to Linux drivers for the hardware, and why does FreeBSD not suffer from this ailment?

mark

[email protected]/[email protected]/[email protected] __________________________
.  .  _  ._  . .   .__    .  . ._. .__ .   . . .__  | Neighbourhood Coder
|\/| |_| |_| |/    |_     |\/|  |  |_  |   |/  |_   | 
|  | | | | \ | \   |__ .  |  | .|. |__ |__ | \ |__  | Ottawa, Ontario, Canada

  One ring to rule them all, one ring to find them, one ring to bring them all
                       and in the darkness bind them...

                           http://mark.mielke.cc/

Let's say it didn't give me a clue how much time was being used and
where. There are various options like bytes swap which could drive up user time, and other things like PIO which drive up system.

I find I give a better quality of help if I understand the problem...

bill davidsen <[email protected]>
  CTO, TMR Associates, Inc
Doing interesting things with little computers since 1979.

As far as I know, when burning an ISO image, the image has 2048 byte sectors to which the CD writer adds error correction data so that the individual sector becomes 2352 bytes. A raw data image includes 2352 byte sectors. The obvious difference would be a higher data rate (2352/2048 or 1.15x more) from computer to writer.

I have seen something similar when reading CD-Rs (with ISO image burnt); After I burn a CD I run readcd -c2scan to see if I get any C2 errors; I am using ASUS 50x CD drive, usually setting the speed to 45x before the operation (my TEAC CD-RW drive always run at 4x when doing readcd -c2scan, which is too slow for my patience).

The interesting thing is that while reading ISO image with dd the system works fine, readcd -c2scan makes it often very unresponsible (just switching between virtual desktops in KDE may take up to several seconds).

The system is Pentium III running at 720 MHz, ABIT RAID-133 motherboard, hard disk connected to HPT-370A, CD and CD-RW drived on separate channels, kernel 2.2.19 + IDE patches, 768 MB RAM.

I am wondering if you could possibly compare the system behaviour with Linux and FreeBSD when using readcd -c2scan (assuming readcd -c2scan works with your drives at some reasonable speeds).

Best regards,

Wojtek

You may try profiling kernel to see where it exactly spending that time. It has an added benefit: you will learn how to profile kernels (if you don't know how to do it already).

I am waiting for similar problem to bite me to learn that, too. :-)

--
vda

It means different write command, additional (possibly less carefully written/tested) driver code etc. You may need to track your problem up to that driver code.
--
vda