Problems with Hauppauge HVR 1600 and cx18 driver

Hi, I just recently bought a Hauppauge Win TV HVR-1600 card and am using it with MythTV running on Ubuntu Intrepid 8.10 64-bit edition.

My hardware is an Asus A8N VM-CSM Motherboard with an Athlon 64 single core CPU.

I'm using the cx18 driver compiled from Mercurial (as of last weekend) and download the latest firmware files available from Hauppauge.

The card is working and I'm able to tune in clear QAM channels on Comcast Cable in Boston.

The
problem is that when recording HD content I see excessive tearing in the recorded video. I thought it might be my on-board video causing this but I transferred a recording over to another machine and the video plays back with the same artifacts and tearing as when I play it on the machine that recorded the video.

I previously had the KWorld ATSC 110 running in the same machine and it recorded HD content with no noticeable visual artifacts on the same cable line.

I've tried tweaking many different settings both in MythTV and in X11 and nothing has made the problem go away.

Is this card perhaps more sensistive to signal disruptions in my cable line perhaps?

If
no, I was thinking that the problem could be due to driver problems in the current development code. Are there any workaround for this problem or should I give up and switch back to my KWorld card?

Thanks very much!

Corey,

As far as I know, with ATSC/QAM you typically won't see the same sort of "tearing" artifacts with a digital source, as those sorts of distortions are usually a product of analog transmission. When you encounter these issues with digital sources, it's usually some product of the video card/X11 during playback.

Perhaps you should make a small clip of MPEG available on a public HTTP server, so people can take a look and offer an opinion.

Devin

Devin J. Heitmueller
http://www.devinheitmueller.com
AIM: devinheitmueller

Hi Devin, thanks for writing back.

I played the recording back on a MacBook Pro in VLC. It still displays the same artifacts.

My KWorld card works just fine with the same cable feed in to the same PC.

Could
it be that this HVR 1600 card is somehow incompatible with my motherboard? I've read in various places that this card works best with PCI 2.3 compliant motherboards. Not sure mine meets that spec.

Anyway, I captured some test video so you can see the problem firsthand.

Here's a link to a file generated by MythTV:

http://onpubco.com/tmp/hvr1600_dtv_sample.mpg (164MB, sorry for the large size! Right-click, save as, etc..)

Here's the cx18 init output:

[   17.737667] cx18:  Start initialization, version 1.1.0
[   17.741016] cx18-0: Initializing card 0
[   17.741021] cx18-0: Autodetected Hauppauge card
[   17.744228] cx18 0000:04:09.0: PCI INT A -> Link[LNKB] -> GSI 18 (level, low) -> IRQ 18
[   17.747652] cx18-0: cx23418 revision 01010000 (B)
[   17.969685] cx18-0: Autodetected Hauppauge HVR-1600
[   17.969687] cx18-0: Simultaneous Digital and Analog TV capture supported
[   18.257142] tuner 3-0061: chip found @ 0xc2 (cx18 i2c driver #0-1)
[   18.287116] cs5345 2-004c: chip found @ 0x98 (cx18 i2c driver #0-0)
[   18.364413] cx18-0: Registered device video0 for encoder MPEG (64 x 32 kB)
[   18.364417] DVB: registering new adapter (cx18)
[   18.493747] cx18-0: DVB Frontend registered
[   18.493750] cx18-0: Registered DVB adapter0 for TS (32 x 32 kB)
[   18.493793] cx18-0: Registered device video32 for encoder YUV (16 x 128 kB)
[   18.493834] cx18-0: Registered device vbi0 for encoder VBI (20 x 51984 bytes)
[   18.493870] cx18-0: Registered device video24 for encoder PCM audio (256 x 4 kB)
[   18.493873] cx18-0: Initialized card: Hauppauge HVR-1600
[   18.508191] cx18:  End initialization
[   33.928073] firmware: requesting v4l-cx23418-cpu.fw
[   34.135866] cx18-0: loaded v4l-cx23418-cpu.fw firmware (158332 bytes)
[   34.161645] firmware: requesting v4l-cx23418-apu.fw
[   34.299395] cx18-0: loaded v4l-cx23418-apu.fw firmware V00120000 (141200 bytes)
[   34.305792] cx18-0: FW version: 0.0.74.0 (Release 2007/03/12)
[   34.512034] firmware: requesting v4l-cx23418-cpu.fw
[   34.658343] firmware: requesting v4l-cx23418-apu.fw
[   34.981741] firmware: requesting v4l-cx23418-dig.fw
[   35.261965] cx18-0 843: loaded v4l-cx23418-dig.fw firmware (16382 bytes)
[   42.284654] cx88/0: cx2388x v4l2 driver version 0.0.6 loaded

Well, no. It's more likely a system level issue.

1. Can you provide the output of

$ cat /proc/interrupts

so I can see what device drivers are sharing IRQ 18 with the CX23418?

2. To turn on debugging to /var/log/messages and save some memory, as root, could you

# service mythbackend stop    (or otherwise kill the backend)
# modprobe -r cx18
# modprobe cx18 debug=7 enc_ts_bufsize=32 enc_ts_bufs=64 \
	enc_yuv_bufs=0 enc_idx_bufs=0

3. Test the digital side of the card with mplayer (you'll need a channels.conf in ~/.mplayer/channels.conf IIRC)

$ mplayer dvb://WFOO-DT -cache 8192

And see if you still see the artifcats.

Stop mplayer and look in your /var/log/messages for things like:

Mar 15 20:26:24 palomino kernel: cx18-0: Could not find buf 28 for stream encoder MPEG
Mar 15 20:26:25 palomino kernel: cx18-0: Skipped TS, buffer 93, 31 times - it must have dropped out of rotation
Mar 15 20:48:07 palomino kernel: cx18-0: Skipped TS, buffer 82, 31 times - it must have dropped out of rotation
Mar 15 20:48:07 palomino kernel: cx18-0: Could not find buf 84 for stream TS
Mar 15 21:01:13 palomino kernel: cx18-0: Fell behind! Ignoring stale mailbox with  inconsistent data. Lost buffer for mailbox seq n
o 2218756
Mar 15 21:01:13 palomino kernel: cx18-0: Skipped encoder VBI, buffer 115, 18 times - it must have dropped out of rotation

or messages about "Possibly falling behind...". These are indicative of a system that can't keep up with the CX23418 firmware for some system level reason.

4. Start up the mythbackend and tune to a digital channel:

# service mythbackend start  (or otherwise restart the mythbackend)

$ mythfrontend

Again check /var/log/messages for "Fell behind", "Possibly falling behind" and buffers that must have "dropped out of rotation". These are signs of a system that is not keeping up in servicing the CX23418 interrupt.

If the sequence numbers in the "falling behind" messages happen quite often or occur in bursts that are very close together, then you will likely see artifacts.

Please provide your /var/log/messages output to the list (or to me, if it is too big).

If you don't have alot of those messages griping about falling behind, it could be RF signal strength related, or it could be something DMA related.

That's a red herring - a bad hypothesis I made a while ago.

What really was the difference is the PCI bridge that is set to subtractive decode. If the PCI-PCI bridge set to subtractive decode is the one the CX23418 is behind, then the bridge retries a failed transaction to the CX23418. On older systems (like many PCI 2.2 systems), the bridge set to subtractive decode is a PCI-ISA bridge, so when a transaction to the CX23418 fails, that PCI-ISA bridge retries it on the ISA bus.

The latest cx18 driver automatically checks retries PCI bus transactions to the CX23418 - so that problem is effectively not an issue.

I have dialup; 164 MB is to big for me to easily work with at the moment.

Regards,
Andy

Hi,

Am Montag, den 16.03.2009, 20:57 -0400 schrieb Andy Walls:

I have a good pipe again.

The file is definitely flawed already at recording level.

At least not fully smooth and recoverable with fairly recent libxine and mplayer stuff, xv and vdpau. Can test it on recent m$ vista stuff as well, but should not make any difference for my experience so far.

Cheers,
Hermann

Andy, thanks for writing back. Here's the info you asked for..

CPU0

  0:        104   IO-APIC-edge      timer
  1:          2   IO-APIC-edge      i8042
  4:          8   IO-APIC-edge    
  7:          1   IO-APIC-edge      parport0
  8:          0   IO-APIC-edge      rtc0
  9:          0   IO-APIC-fasteoi   acpi
 12:          4   IO-APIC-edge      i8042
 14:     777839   IO-APIC-edge      pata_amd
 15:          0   IO-APIC-edge      pata_amd
 17:     760893   IO-APIC-fasteoi   EMU10K1
 18:     189462   IO-APIC-fasteoi   cx18-0
 19:    5936140   IO-APIC-fasteoi   nvidia
 20:   19869131   IO-APIC-fasteoi   eth0
 21:     158197   IO-APIC-fasteoi   sata_nv
 22:          2   IO-APIC-fasteoi   ehci_hcd:usb2
 23:        307   IO-APIC-fasteoi   ohci_hcd:usb1
NMI:          0   Non-maskable interrupts
LOC:    6194711   Local timer interrupts
RES:          0   Rescheduling interrupts
CAL:          0   function call interrupts
TLB:          0   TLB shootdowns
TRM:          0   Thermal event interrupts
THR:          0   Threshold APIC interrupts
SPU:          0   Spurious interrupts

ERR: 1

I didn't test with mplayer, but I played some Live TV in MythTV and here is some debug output I got once I started watching. The video was still tearing and artifact-ing.

Mar 17 20:54:19 codebeast kernel: [96935.942665] cx18-0:  info: Start feed: pid = 0x1ffb index = 7
Mar 17 20:55:41 codebeast kernel: [97017.160151] cx18-0:  warning: sending CX18_CPU_DE_SET_MDL timed out waiting 12 msecs for RPU acknowledgement
Mar 17 20:55:56 codebeast kernel: [97032.184180] cx18-0:  warning: sending CX18_CPU_DE_SET_MDL timed out waiting 12 msecs for RPU acknowledgement
Mar 17 20:55:56 codebeast kernel: [97032.280670] cx18-0:  warning: sending CX18_CPU_DE_SET_MDL timed out waiting 12 msecs for RPU acknowledgement
Mar 17 20:56:12 codebeast kernel: [97048.676352] cx18-0:  warning: sending CX18_CPU_DE_SET_MDL timed out waiting 12 msecs for RPU acknowledgement
Mar 17 20:56:30 codebeast kernel: [97066.160835] cx18-0:  warning: sending CX18_CPU_DE_SET_MDL timed out waiting 12 msecs for RPU acknowledgement
Mar 17 20:56:31 codebeast kernel: [97067.260070] cx18-0:  warning: sending CX18_CPU_DE_SET_MDL timed out waiting 12 msecs for RPU acknowledgement
Mar 17 20:57:17 codebeast kernel: [97113.900127] cx18-0:  warning: sending CX18_CPU_DE_SET_MDL timed out waiting 12 msecs for RPU acknowledgement
Mar 17 20:57:23 codebeast kernel: [97119.308397] cx18-0:  warning: sending CX18_CPU_DE_SET_MDL timed out waiting 12 msecs for RPU acknowledgement
Mar 17 20:57:48 codebeast kernel: [97144.551274] cx18-0:  info: Stop feed: pid = 0x0 index = 0

Do I need a new motherboard?

This board only has 2 PCI slots. The other one is populated with an SB Live 5.1 sound card. Should I try removing the sound card and put the TV card in its place? I can always use the on-board sound if the SB Live card is causing some sort of conflict or IRQ contention.

What about tweaking my BIOS settings. Would messing with IRQ or HyperTransport settings make a difference? Does my motherboard not have the bandwidth to keep up with this card?

Thanks again!

OK.

Nothing's sharing the intterupt line with the cx18. The cx18 IRQ is a higher priority than, the apparently busy, nvidia and eth0 driver IRQs.

The paralled ATA (IDE) disk controller on IRQ 14 seems to be accessed a lot. Is that your system drive, or where recordings get stored, or something else?

First, I'm somewhat surprised you got only these. I'll assume you were able to turn the driver debugging on and this is all you got during a single digital capture.

The messages are, well, normal. That doesn't make them right, but they do happen. Here's how:

When an application, like MythTV, reads data from the cx18 driver, and empties an internal driver buffer, the driver immediately tries to return the buffer to them CX23418 firmware with a CX18_CPU_DE_SET_MDL call and waits for an interrupt from the CX23418 to acknowledge the command.

Most of the time, the CX23418 firmware immediately acknowledges the buffer handover with an interrupt. Then cx18 driver then goes back to providing data to the application and eventually completes the application's read() call and returns control to the application (MythTV).

Some of the time the CX23418 firmware doesn't respond for a really long time. While the cx18 driver is waiting for the firmware to respond, the driver "sleeps" (for up to 10 ms) in the application's (MythTV's) call to read(). This means MythTV is getting suspended for up to 12 msec at a time when this happens. For a timing reference, an NTSC video field happens every 17 mesc or an NTSC frame happens every 33 msec.

I don't know why the CX23418 firmware takes so long to respond with an acknowledgement sometimes. I picked the value 10 ms as a timeout, because experiments had shown that gave enough time for all but the worst outlyer delays to be acknowledged. I suppose I could modify the driver to give back buffers in a workhandler and not delay the application (MythTV) call to read().

Looking at your data, these long timeouts occured at intervals of 82, 15, 0.096, 16, 18, 1.1, 47 and 5 seconds apart. Do those intervals correspond to about when you see the "tears" is the recorded video?

First let me say, that most multimedia systems that I have seen (that excludes HTPCs), have more than one processor or core. The few extra dollars make a lot of annoying problems a non-issue. The does not mean a single processor machine like yours can't do the job.

Do you have to replce your motherboard? I'm going to give you a qualified "no". Not until you take some steps to try and improve things with what you have.

1. Change line 567 in linux/drivers/media/video/cx18/cx18-mailbox.c from

	timeout = msecs_to_jiffies((info->flags & API_FAST) ? 10 : 20);

to

	timeout = msecs_to_jiffies((info->flags & API_FAST) ? 2 : 20);

and recompile and reinstall the cx18 driver. See if the artifacts are less frequent. You'll likely get more log messages about CX18_CPU_DE_SET_MDL timing out, but they are just a warning. The firmware seems to get them OK anyway, despite not sending an acknowledgement.

2. Try modifying the enc_ts_bufsize module parameter from it's default of 32 k, down to 4 k or up to 128 k. With a smaller size, the loss of any one buffer from the encoder will not have such a devastating effect on the MPEG TS, but interrupts will happen more frequently. With a larger size, you're less likely to see the timeout errors in your logs, and the interrupt rate will be lower.

Make sure you use enc_ts_bufs=64 when you set the buffer size small.

3. Check if you system states it is using SWIOTLB in the dmesg or /var/log/messages log. This means that some DMA buffers on your system *may* have to be copied around by the kernel with memcpy after PCI hardware DMA's data into memory. This is generally undesirable as it consumes CPU that could be used for other things.

4. Try and keep uneeded hardware devices (the ethernet controller, other disks aside from where the data is being recorded) as "quiet" as possible when capturing video. The PCI bus is a shared bus between devices and driver interrupt routines will disable the single CPU from servicing interrupts. This will mean less time on the bus from the CX23418 hardware and/or delays in servicing interrupts from the CX23418.

5. Try and write the video recordings to the SATA disk drive, vs one that is connected to the parallel IDE interface (ribbon cable).

6. Try recording video without watching it at the same time (a scheduled recording). When you watch it later, are the artifacts there?

No. The amount of data needed by the sound card over a given time period is rather small. If the linux driver for the EMU10K1 has a sensible irq_handler that doesn't keep interrupts disabled for too long, then I doubt it's a big factor.

You can if you want. But you're only trading one sound card and linux driver for another. The biggest difference would be which one has the linux driver that has an irq_handler that keeps interrupts disabled for the shortest amount of time.

The only thing I can think that might help there is having the IDE devices connected to the parallel IDE interface run at the fastest mode available. That's usualy the BIOS default though.

I don't know. I have very little details on it. But...

A PCI bus is a PCI bus. The PCI bus width is 32 bits and the clock period is 30 ns. Maximum IO bandwidth for any PCI bus motherboard with the same mix of IO devices we be comparable.

CPU thoughput (MIPS) may be an issue. Another core or CPU makes life easier.

Interuupt processing latency may be an issue. If linux drivers are keeping interrupts disabled for too long in their irq_handlers, other drivers suffer. This has a larger impact on single processor machines.

You're welcome.

Regards,
Andy

Andy,

I am noticing an improvement in pixelation by setting the bufsize to 64k. I will monitor over the next week and report back. I am running 3 HVR-1600s and the IRQs are coming up shared with the USB which also supports my HD PVR capture device. Monday nights are usually one of the busier nights for recording so I will know how well this holds up.

Thanks for the tip!

Brandon

Hi Andy and Brandon, I too tried various different bufsizes as suggested and I still see very noticeable pixelation/tearing regardless of the setting.

I even upgraded my motherboard this past weekend to an Asus AM2+ board with Phenon II X3 CPU. Still the same problems with the card in a brand new setup.

I also tried modifying the cx18 source code as Andy suggested and that made more debug warning show up in my syslog, but still did not resolve the issue. Haven't tried this yet with the new motherboard though.

Is it possible that this card is more sensitive to hiccups in the signal coming from the cable line? Or interference from other close-by cables and electronic equipment?

When recording/watching Live TV through MythTV, I see that ffmpeg is constantly outputting various errors related to the video stream. I can post those here if you think it's relevant.

Shoud I just return this card and get one with a different chipset? Or do you think driver updates can solve the issue?

I'm happy to hold on to this card if it means I can contribute in some way to fixing the problem, if it's fixable : )

Hmmm. If you can find the time to do any of the following tests, it may help narrow down what is (or cannot be) wrong:

1. When running a digital capture in MythTV, run "femon" in another window. Do you get notable variations in Signal or SNR or momentary jumps in BER or UNC?

2. Do you have any "hiccups" or artifacts with analog video captures (Tuner or Svideo or Composite)?

3. If analong signals come from the cable company, with the cable connected to the analog tuner input, do any channels show any ghosting, herring bone, or faint images of other channels?

4. With a UHF antenna connected to the digital input, and pointed to the closest major broadcaster, does ATSC 8-VSB suffer the same artifacts as QAM (provided you can get a decent signal)?

OK. CPU isn't a bottleneck anymore. :)

It still could be a signal level, driver or kernel problem.

Ground loops (noise on the cable shield) can be a problem. Hopefully looking at femon output can give us a sense of if that is a problem.

You can always check this list of tips for improving signal quality:

http://www.ivtvdriver.org/index.php/Howto:Improve_signal_quality

Those errors have their source in one of 2 places:

1. Incoming buffers from the CX23418 are being missed by the cx18 driver due to system inability to service the interrupt in a reasonable time. The result is lost TS buffers.

2. There are periods of high bit errors or loss of lock with demodulating the signal. The result is lost parts of the TS.

(BTW, I do a lot of testing with ATSC 8-VSB and none with QAM - no cable.)

If you want you can turn on maximum debugging (the debug=511 module option) and run a digital capture. If you can, try and find in /var/log/messages the timestaps that correspond roughly to about when artifacts happen. (With that much logging, playback performance may just be horrible though.)

Then zip up the likely enormous log file and send it to me.

Regards,
Andy

Corey and Brandon,

I found a race condition between the cx driver and the CX23418 firmware. I have a patch that mitigates the problem here:

http://linuxtv.org/hg/~awalls/cx18/rev/9f5f44e0ce6c

I think the final form of the patch could be better. However, this patch essentially eliminated any artifacts I was getting playing back digital TV. I also had positive results running mplayer without the "-cache" command line for both digital and analog captures.

I haven't tested on a single processor machine, nor in a multicard setup, but things looked good enough that I thought it ready for test by others.

Let me know if it helps or not.

Regards,
Andy

A race like this should be avoidable. The way it works is you do something like this:

/* 1 */ set_current_state(TASK_INTERRUPTIBLE);
/* 2 */ cx18_write_reg_expect(cx, irq, SW1_INT_SET, irq, irq); /* 3 */ schedule();
/* 4 */ ack_has_now_been_received();

The race you are talking about is when the ack arrives between line 2 and
3. If this happens here, the process' current state is changed to TASK_RUNNING when the irq hander that receives the ack tries to wake our process. If schedule() is called with the state set to TASK_RUNNING then the process doesn't sleep. And thus there is no race. The key is that preparing to sleep at line 1 happens before we start the event we want to wait for at line 2.

wait_event() should take care of this. wait_event(q, test) basically does:

for(;;) {
	// point A
	add_me_to_waitqueue(q);
	set_current_state(TASK_UNINTERRUPTIBLE);
	if (test)
		break;
	// point B
	schedule();
}

clean_up_wait_stuff();

If your event occurs and wake_up() is called at point A, then the test should be true when it's checked and schedule() is never called. If the event happens at point B, then the process' state will have been changed to TASK_RUNNING by wake_up(), remember it's already on the waitqueue at this point, and schedule() won't sleep.

I think what's probably happening is the test, cx18_readl(cx, &mb->ack) == cx18_readl(cx, &mb->request), is somehow not true even though the ack has been received. Maybe a new request was added?

I think calling wait_event()'s with something that tests a hardware register is a little iffy. It's better if the irq handler sets some driver state flag (atomically!) that indicates the event you were waiting for has happened and then you check that flag.

Trent,

First, thanks for the fresh perspective.

I tried something like this in my second iteration, see below. (The patch I put in my repo was actually my third iteration.)

As you know, the condition is checked even before this loop is entered, to avoid even being even added to a waitqueue. (Thank God for ctags...)

As you may have noticed, the original code was using wait_event_timeout() before like this:

        CX18_DEBUG_HI_IRQ("sending interrupt SW1: %x to send %s\n",
                          irq, info->name);
        cx18_write_reg_expect(cx, irq, SW1_INT_SET, irq, irq);

        ret = wait_event_timeout(
                       *waitq,
                       cx18_readl(cx, &mb->ack) == cx18_readl(cx, &mb->request),
                       timeout);

Because waiting for the ack back is the right thing to do, but certainly waiting too long is not warranted.

This gave me the occasional log message like this:

1: cx18-0:  irq: sending interrupt SW1: 8 to send CX18_CPU_DE_SET_MDL
2: cx18-0:  irq: received interrupts SW1: 0  SW2: 8  HW2: 0
3: cx18-0:  irq: received interrupts SW1: 10000  SW2: 0  HW2: 0
4: cx18-0:  warning: sending CX18_CPU_DE_SET_MDL timed out waiting 10 msecs for RPU acknowledgement

Where line 1 is the driver notifiying the firmware with a SW1 interrupt. Line 2 is the firmware responding back to the cx18_irq_handler() with the Ack interrupt in SW2 (the flags match, 8 & 8, by design). Line 3 is an unrelated incoming video buffer notification for the cx18 driver.
Line 4 is the wait_event_timeout() timing out.

Since, I'm sending buffers back to the firmware on the read()-ing applications timeline, these delays caused playback problems.

OK, for some reason, I thought schedule() and schedule_timeout() would go to sleep anyway.

A PCI bus read error could be the culprit here. That's the only thing I can think of. We only get one notification via IRQ from the firmware.

No, I lock the respective epu2apu or epu2cpu mailboxes respectively with a mutex.

I was toying with setting an atomic while in the IRQ handler. But then I realized when we get the ack interrupt, the firmware should actually be done. So really the wakeup() is the only indicator I really need. Checking for ack == req is just a formality I guess.

There wasn't a wait_timeout(), so I had tried something like this in my first iteration:

#define wait_event_oneshot_timeout(wq, condition, timeout)              \
({                                                                      \
        long __ret = timeout;                                           \
        if (!(condition)) {                                             \
                DEFINE_WAIT(__wait);                                    \
                prepare_to_wait(&wq, &__wait, TASK_UNINTERRUPTIBLE);    \
                if (!(condition)) {                                     \
                        __ret = schedule_timeout(__ret);                \
                }                                                       \
                finish_wait(&wq, &__wait);                              \
        }                                                               \
        __ret;                                                          \

})

...

	cx18_write_reg_expect(cx, irq, SW1_INT_SET, irq, irq);

        ret = wait_event_oneshot_timeout(*waitq,
                                         cx18_readl(cx, &mb->request) ==
                                         cx18_readl(cx, &mb->ack),
                                         timeout);

...

It didn't work. Sometimes it would wait the whole timeout, but the cx18_irq_handler() had gotten an ack interrupt.

Then I tried:

        // FIXME break into several small timeouts/poll
        // or use an atomic to communicate completion
        CX18_DEBUG_HI_IRQ("sending interrupt SW1: %x to send %s\n",
                          irq, info->name);
        ret = timeout;
        prepare_to_wait(waitq, &w, TASK_UNINTERRUPTIBLE);
        cx18_write_reg_expect(cx, irq, SW1_INT_SET, irq, irq);
        /*
         * Will we schedule in time, before the IRQ handler wakes up our waitq? 
         * Who knows?!  How exciting!  Let the race begin!
         */
        if (req != cx18_readl(cx, &mb->ack))
                ret = schedule_timeout(timeout);
        finish_wait(waitq, &w);

It didn't work, sometimes it would wait the whole timeout even though the ack interrupt had arrived. Again at the time, I was under the impression that schedule_timeout() would go to sleep anyway even if we had been awakened (thus my sarcastic comments).

Did I miss anything with either of those two previous tries?

I guess I need to dig into the guts of schedule_timeout() to convince myself that the process won't be put to sleep.

I'm using Fedora 10 BTW:

Linux palomino.walls.org 2.6.27.9-159.fc10.x86_64 #1 SMP Tue Dec 16 14:47:52 EST 2008 x86_64 x86_64 x86_64 GNU/Linux

Thanks.

Regards,
Andy

I think the initial check of the condition is just an optimization and everything will still work without it. Seeing as all this is inlined, I wonder if it's a good optimization...

Could it be that the wait_event doesn't actually run and check its condition until _after_ line 3? In that case SW2 != 8 and so it goes back to sleep? Calling wake_up() just makes the processes on the waitq runnable, they don't actually run until later, possibly much later.

AFAIK, they'll still cause the kernel schedule a process. Maybe a different process. But the original process is still in TASK_RUNNING state and so still in the run queue and will get run again. If it was in TASK_(UN)INTERRUPTIBLE state then it wouldn't be in the run queue and wouldn't run again until something woke it up.

But in your log:

Isn't the wait_event_timeout() waiting until line 4? And doesn't line 3 mean something has changed the registers? Changed them before the wait_event finished?

If you use an interruptible timeout, then you could get interrupted with a signal before the irq handler has woken you.

It's called sleep_on_timeout(q, timeout).

I guess it depends on how expensive prepare_to_wait() is since it acquires a spinlock.

But now that you mention inlining. I now have to check if this sequence that I thought didn't work:

        prepare_to_wait(waitq, &w, TASK_UNINTERRUPTIBLE);
        cx18_write_reg_expect(cx, irq, SW1_INT_SET, irq, irq);
        if (req != cx18_readl(cx, &mb->ack))
                ret = schedule_timeout(timeout);
        finish_wait(waitq, &w);

is actually getting reordered. I bet constituent parts of the first two lines may be. That would certainly explain things.

SW2: 8 is a firmware response to us setting the outgoing SW1 to 8.

SW2 getting cleared is done by cx18_irq_handler and its helper:

static void xpu_ack(struct cx18 *cx, u32 sw2)

{
	// Wake up the process waiting on the EPU -> CPU mailbox ack
	// This one has a flag value of 8
        if (sw2 & IRQ_CPU_TO_EPU_ACK)
                wake_up(&cx->mb_cpu_waitq);
	// Wake up the process waiting on the EPU -> APU mailbox ack
        if (sw2 & IRQ_APU_TO_EPU_ACK)
                wake_up(&cx->mb_apu_waitq);
}

irqreturn_t cx18_irq_handler(int irq, void *dev_id)

{
        struct cx18 *cx = (struct cx18 *)dev_id;
        u32 sw1, sw2, hw2;

	// Get the status of SW2
        sw2 = cx18_read_reg(cx, SW2_INT_STATUS) & cx->sw2_irq_mask;

	// Clear any status of SW2 that were found set
        if (sw2)
                cx18_write_reg_expect(cx, sw2, SW2_INT_STATUS, ~sw2, sw2);

	// Act on any SW2 interrupts found set
        if (sw2)
                xpu_ack(cx, sw2);

        return (sw1 || sw2 || hw2) ? IRQ_HANDLED : IRQ_NONE;
}

If SW2 got set back to 0 (or != 8), that means we cleared it ourselves. We only do that slightly prior to waking up the proper waitq.

Hmm. Maybe then we're yielding the processor and then simply running much later.

If that's the case, I may be stuck with shorter timeouts with polls. :(

I'm going to have to figure out how to profile things.

First a note:

There are four mailboxes the driver cares about EPU -> CPU, CPU -> EPU,
EPU -> APU, and APU -> EPU. We mostly care about the EPU/CPU
mailboxes.

Line 1 indicates an outgoing command in the EPU -> CPU mailbox Line 2 indicates an ack was placed in the EPU -> CPU mailbox Line 3 indicates an incoming command in the CPU -> EPU mailbox Line 4 indicates the async notification in Line 2 being missed by
us somehow

So

yes, wait_event_timeout() is waiting until line 4.
yes, line 3 means we cleared the SW2 register when we got line 2, yes, line 3 also means the firmware is sending us a full capture buffer

     with information in the CPU -> EPU mailbox (not the mbox at issue)

But, line 3 does not mean the EPU -> CPU mailbox ack changed, Line 2
tells us that should be the case (different mailboxes)

The process of the IRQ handler clearing SW2 should have resulted in the IRQ handler also sending a wake_up(). It doesn't appear to happen a small percentage of the time.

I used UNITERRUPTIBLE here because it doesn't quite make sense to inidcate -ERESTARTSYS back to the caller in all circumstances. This function can be called by read() to send a series of commands to start a capture or to just send back a drained buffer; poll() to send a series of commands to start a capture; or by the work handler to return a drained buffer.

I was deterred by the big scary comment:

/*
* These are the old interfaces to sleep waiting for an event.
* They are racy. DO NOT use them, use the wait_event* interfaces above.
* We plan to remove these interfaces.
*/
extern void sleep_on(wait_queue_head_t *q);
extern long sleep_on_timeout(wait_queue_head_t *q,

                                      signed long timeout);

Again, thanks for helping me think this through. It's obvious I have more testing and troubleshooting to do.

My first step will be to check to see if compiler reordering screwed up one of my prior patch attempts.

Regards,
Andy

Hi Andy,

I have cloned this tree and loaded on the server. I'll let you know over the next couple of days if there is any improvement.

Thanks!

Brandon

Andy,

Based on continued discussions it seems you're still exploring things. I can tell you that the analog captures are still exhibiting artifacts. I'll get to some of the HD captures tonight.

Brandon

Well, the patch you have to work with essentially does a poll every 1/4 of a millisecond (a rate of 67 times per NTSC field while polling) with a wait between the polls. If you're still getting artifacts, then I suspect your artifacts problems may not lie where I'm looking right now.

I have no artifacts with analog captures, so let me get through this first problem and then I'll ask more about your symptoms. I don't have a 3 HVR-1600 card setup. You may try setting enc_mpg_bufsize to a value different than 32 kB. Setting it higher will make you less likely to lose buffers due to the firmware timing out when it sends buffers to the driver. Setting it lower will make the loss of any one buffer of less impact to the stream, and setting the analog capture to provide TS vs the deault of a PS may help too.

OK.

Regards,
Andy

Brandon and Corey,

I have a series of changes to improve performance of the cx18 driver in delivering incoming buffers to applications. Please test the code here if you'd like:

http://linuxtv.org/hg/~awalls/cx18-perf/

These patches remove all the sleeps from incoming buffer handling (unless your system starts getting very far behind, in which case a fallback strategy starts letting sleeps happen again).

If you still have performance problems, there is one more patch I can add, that avoids some sleeps in the new work handler threads that pass empty buffers back out to the firmware. A copy of that patch is here:

http://linuxtv.org/hg/~awalls/cx18/rev/b42156ceee11

The trade-off I had to make with all these patches was to have the cx18-driver prefer to "spin" rather than "sleep" when waiting for a resource (i.e. the capture stream buffer queues), while handling incoming buffers. This makes the live playback much nicer, but at the expense of CPU cycles and perhaps total system throughput for other things. I'd be interested in how a multicard multistream capture fares.

BTW, the above cx18-perf repo is missing a very small patch to fix a recent bug with line-in audio not working. If you need line-in audio to work during testing, a patch is in the main v4l-dvb repo already:

http://linuxtv.org/hg/v4l-dvb/rev/d19938a76e7a

Regards,
Andy

Andy,

I apologize for the delay in this email. I have been fighting an issue with lirc which has preoccupied my time (it is amazing how ticked the family gets when they can't watch TV!) I have mitigated that issue and have been running your updated drivers for a couple of days with marked improvement. I am seeing some messages in dmesg (normal?) and I have attached it along with lspci, lsusb, and lsmod. The majority of our recordings have been making use of the digital connection with OTA ATSC. Also, because of my reduced tuner control issues (lirc) I have not run any simultaneous captures with the HDPVR active.

The system is running Ubuntu Jaunty RC1 9.04 fully patched and kernel
- Linux sagetv-server 2.6.28-11-server #42-Ubuntu SMP Fri Apr 17 02:45:36 UTC 2009 x86_64 GNU/Linux

I use SageTV for PVR which uses the drivers in 32-bit compatible mode.

Brandon

Good to hear.

The messages indicate that the cx18 driver's interrupt handler is not being called in time to service a CX23418 interrupt for an incoming capture buffer. This indicates a latency prbolem in the system.

I also will note that the missed buffers are happening at inervals that are somewhat far apart: ~1000 seconds, ~400 seconds, ~200 seconds, ~1600 seconds, etc...

1. Since you have a 4 core system that looks to be pretty high-end, I'll assert the fundamental trade-off I mention above, about the cx18 driver spinning vs. sleeping when handling incoming buffers in the work handler, is likely not the cause.

2. Since the cx18_irq_handler() only seems to be called late in the case of interrupts from cx18-1 and not cx18-0 nor cx18-2, I'll assert that a driver servicing hardware that shares the interrupt line with cx18-1 is likely involved.

IRQ 20 is shared by

	cx18-0 at PCI 0000:05:00.0

IRQ 18 is shared by
cx18-2 at PCI 0000:05:02.0
usb hub 5 at PCI 0000:00:1a.7 (no usb devices connected) usb hub 8 at PCI 0000:00:1d.2 (no usb devices connected)

IRQ 19 is shared by

	cx18-1 at PCI 
	usb hub 7 at PCI 0000:00:1d.2
		a usb device, Cygnal Systems (microcontroller?), is connected (commandIR?)
	ahci disk controller at PCI 0000:03:00.0 (1? disk connected)
	ahci disk controller at PCI 0000:00:1f.2 (a few disks connected)
		(looks to be using Message Signalled Interrupts at IRQ 2299 though)

My hypothesis is that the ahci_interrupt() handler routine in linux/drivers/ata/achi.c is not acknowledging IRQ 19 in a timely manner and not finishing up interrupt service rapidly under certain conditions. And looking at that routine, it does *all* its work first, before clearing the interrupt line from the AHCI controller. The achi_interrupt() routine acquires a spinlock of its own and then some of the routines it calls can also try to acquire spinlocks. One can hypothesize that the achi_interrupt() routine might occasionally take a long time to complete.

While the ahci_interrupt() handler is doing its work and not clearing the disk controller interrupt line on IRQ 19 and returning, any CX23418 interrupts on IRQ 19 will go unserviced during that time. This is how the cx18 driver could miss an incoming buffer, as the CX23418 won't wait long for the cx18 driver to pick up the buffer id from the mailbox.

Things you could try:

1. Setting the priority of cx18-1 lower than cx18-0 and cx18-2 when SageTV has a choice of which card to use for video captures. Also note if you ever see the message for cx18-0 or cx18-2 and how often.

2. Record TV programs to a disk other then the one hanging off of that disk controller at PCI 3:00.0. That would include temp storage used during the recording process (e.g. /tmp/... /var/... ). The goal is to keep that disk quiescent during captures from cx18-1.

3. Move the disk controller in question to another PCI slot. See if the problem leaves the CX23418 on IRQ 19, cx18-1, (and maybe begins to affect another CX23418 if the disk controller gets IRQ 18 or IRQ 20 as its new IRQ).

4. Move that one disk to a different disk controller that isn't using IRQ 18, 19, or 20.

5. Try increasing the PCI latency timer larger than 64 PCI bus clocks on the PCI bridge which the CX23418 and AHCI disk controller are behind. That *might* help the ahci_interrupt() handler to finish it's work a little earlier, and *maybe* mitigate things.

6. Contact the AHCI driver maintainer and ask him to help you confirm or refute my hypothesis -- I don't know the most efficient and safest way to verify my hypothesis by twiddling in the ahci driver. The ahci.c file has this info:

 *  Maintained by:  Jeff Garzik jgarzik * pobox.com
 *                  Please ALWAYS copy [email protected]
 *                  on emails.

This probably doesn't matter. This is a latency issue from:

the time the CX23418 asserts its PCI bus interrupt line

to

the time the cx18 driver's irq handler can read the buffer id information from the CX23418 mailbox.

I have thoroughly tweaked the cx18_irq_handler()'s timeline in previous changesets. There are literally no improvements to be made in it.

You either have all your CPU's busy (doubtful), or a shared interrupt line that isn't being serivced quickly by all the device drivers handling that line. I can't think of anything else.

Regards,
Andy