Negative Presentation Time in DirectShow

Question

This one is really making me pull my hair out. I have written a DirectShow transform filter derived from CTransformFilter. I have derived an input pin from CTransformInputPin. When my input pin's Receive method is called, it logs the IMediaSample's presentation times to a file. This all works fine until I stop the graph and start it again (I am using MS's graphedt). Most of the time, upon running again, there are no problems. But, about one out of every dozen or so times that I stop and then run the graph again, the starting presentation time is negative. It eventually increases to, and rises above, zero, as the graph runs, but it never catches up with the stream time, with the result that the stream time remains significantly head of the presentation start time for every sample.

I have observed this with a Logitech Webcam Pro 9000 and a Logitech C600 camera, but not with a Winbook camera, so I am wondering if this is a Logitech problem. Has anyone else seen negative presentation times on video IMediaSamples after stopping and running again? (I have looked at the preroll flag in the IMediaSample: it is always S_FALSE.)

UPDATE:

I have overridden CTransformFilter's (actually, CBaseFilter's) Run method with this:

STDMETHODIMP MyTransformFilter::Run(REFERENCE_TIME tStart)
{
    char buff[1000];
    REFERENCE_TIME rTime;

    m_pClock->GetTime(&rTime);
    sprintf(buff, "Run tstart = %lld, rTime = %lld", tStart, rTime);
    Trace(buff); // open my log file, add buff, close my log file
    return CTransformFilter::Run(tStart);
}

I used graphedt to start the graph, run for 10 seconds, pause for 5 seconds, then start again. Here's the output:

Run tstart = 7855978550000, rTime = 7855978450000
Run tstart = 7856030610000, rTime = 7856126960000

The two times passed to Run differ by 5.2 seconds (about the amount of time I paused). The two reference clock times differ by 14.6 seconds (about the total time between calls to Run). Except for the slight increase the filter graph manager adds to the time passed to Run (10 mS, in the first call), I would expect these to be the nearly the same every time Run is called. Instead, the time passed to Run on the second call is about 10 seconds behind the reference clock. I would be extrememly grateful for help in understanding why the time passed to Run on the second call is not (almost) the same as the time returned by the reference clock on the second call.

UPDATE 2:

Problem appears to be in the Logitech version 13.31.1044.0 driver. See Answer, below.

Answer 1

After quite a bit of experimentation, I have concluded that the problem is most likely specific to the Logitech 13.31.1044.0 camera driver. With the earlier Logitech 12.10.1110 driver, with the Winbook DC-6120 camera (and its driver), and the Chicony USB 2.0 camera (and its driver) I have not been able to make the problem recur. For no apparent reason, the Logitech 13 driver will deliver samples starting with negative presentation times on about one out of every dozen-or-so times a graph including it restarts (that is, after I have stopped it in graphedt and then started it again). Comparing these times to the stream time does not provide the information MSDN describes as to whether or not the sample is scheduled for display in the past, present, or future, as the stream time does not appear to be affected. On every restart, stream time begins again at zero, as one would expect, regardless of what time the camera's presentation times begin. (Note that the Logitech is streaming in RGB24 subtype, with no compressed frames.)

I am working on a multi-threaded pass-through filter that may be able to reassign the presentation times with values based on the stream time, and do so fast enough to "fake" correct values, and will post here if I get a meaningful result. Also, I will document my tests and communicate them to Logitech. If they respond, I'll post that here, too.

If anyone else is working with the Logitech products that use the above-mentioned driver (or otherwise observe the behavior I have described), please comment here. I'd be pleased to send you a copy of my filter, which logs the times, frames, and so on. We might be able to work together on finding a good way to deal with this.

UPDATE

By writing the simplest possible Tranform filter that I could (one that simply copies a negative image of the input IMediaSample to the output), I have been able to reproduce this behavior fairly consistently. About one of every five or six times I restart a graph consisting of Camera->Filter->Renderer, the first few samples are delivered with negative frame times that are way behind the stream time, and which never catch up. (That is, the stream time stays permanently ahead of the samples' presentation times). Again, this never happens with other cameras, nor with the older Logitech driver.

Here's the interesting part: If I add some delay to the filter's Run method (after overriding CTransformFilter::Run), the problem goes away. Here's the code:

STDMETHODIMP DLPassThrough::Run(REFERENCE_TIME tStart)
{
    Sleep(10);

    return CTransformFilter::Run(tStart);
}

I can make the problem come and go by commenting out or restoring that "Sleep(10)" call. All I can guess is that the camera code is multi-threaded and needs some time between the "Pause" call that always precedes a "Run" call, and the next "Run" call it gets, to clean up what it's doing. As I understand the MSDN docs, the graph manager will call "Pause" on the renderer, then my filter, then the camera, before going back and calling "Run" on the renderer, my filter, and then the camera. I believe each of those calls is synchronous, but if the camera code is multi-threaded, it may still be working on its most recent "Pause" call from the graph manager when its "Run" method is called. By adding a delay to my filter's "Run" method, there is a longer delay between the most recent "Pause" call to the camera, and the next "Run" call to the camera.

Still waiting/hoping to hear back from Logitech about this. Meanwhile, I did write a multi-threaded transform-in-place filter that simply adds a reference to the latest sample it gets, replaces its presentation times with the current stream time, saves it for the downstream filter to use the next time the downstream filter is ready to receive it, and then goes back to waiting for the next incoming sample. (If more than one sample comes in before the downstream filter will take one, the previous sample is released, and replaced with the latest one.) Seems to be working, so far.

UPDATE 2

Here is Logitech's answer:

I would like to inform you that the device was made mainly to work for IM applications for video streaming and not as a subject for developing software or filters.

Answer 2

Negative time is not a big deal. Essentially it means "the media sample should have been presented a while ago". So you might think that the media sample could be discarded? Sometimes this is trues, sometimes it is not: imagine a sequence of temporally compressed video frames with a key frame followed by 10 delta frames. You want presentation to start from frame #5, how can you do it? You have to push through from the key frame so that decoder could effectively decode from the splice point, otherwise it cannot start with delta frame. A decoder might delivers the output frame regardless of whether the frame is late or not, and this is how those frames eventually reach you.

Another scenario which results in negative time is caused by race condition of threads, streaming and controlling. The capture thread might be starting its operation yet not having base "start time" on hands.