question about time

[ddvlamin]

Hi,

We are testing some new algorithms on P300 data that we previously recorded. However we had some weird problems and consequently we set up a simple scenario with a generic stream reader (that reads the P300 file) and an stimulation based epoch box, we added some debug output to the epoching box and this was the output

[ INF ] At time 9.906 sec <Box algorithm::Stimulation based epoching> Created new epocher for stimulus OVTK_StimulationId_Label_01 at time 9.898 sec:9.898 sec:10.898 sec
[ INF ] At time 9.930 sec <Box algorithm::Stimulation based epoching> Still processing epoch for stimulation OVTK_StimulationId_Label_01 with timestamps 9.898 sec:9.898 sec:10.898 sec
[ INF ] At time 9.930 sec <Box algorithm::Stimulation based epoching> Chunk start time: 9.656 sec, chunk end time: 9.688 sec

So the epocher was created around the time that the stimulus is received in the epoching box, i.e. perfect. A few cycles later at 9.93sec it processes its first chunk, but that chunk is timestamped at the time almost 250ms earlier. In an online scenario I could expect something like this when the processing runs late, but this is read from a file. Could it be that the file was not recorded well (although perfect classification was achieved on later files based on this training file) and that the chunks have not received the correct timestamp? What I would expect is the following where I replaced the file reader with a sinus oscillator:

[ INF ] At time 9.898 sec <Box algorithm::Stimulation based epoching> Created new epocher for stimulus OVTK_StimulationId_Label_01 at time 9.898 sec:9.898 sec:10.898 sec
[ INF ] At time 10.008 sec <Box algorithm::Stimulation based epoching> Still processing epoch for stimulation OVTK_StimulationId_Label_01 with timestamps 9.898 sec:9.898 sec:10.898 sec
[ INF ] At time 10.008 sec <Box algorithm::Stimulation based epoching> Chunk start time: 9.875 sec, chunk end time: 10.000 sec

Here the chunk ranging from 9.875 to 10 sec is indeed processed not much later than 10sec. What causes the mismatch between the current time and the chunk times in the first scenario where one reads from the file?

Best regards,
Dieter

[lbonnet]

Hi Dieter,

We saw that you added the 2 debug messages, the first one being already in the original source code.
For the record, the 3 dates printed are (stim date : stim date + offset : stim date + offset + duration)

[ INF ] At time 9.906 sec <Box algorithm::Stimulation based epoching> Created new epocher for stimulus OVTK_StimulationId_Label_01 at time 9.898 sec:9.898 sec:10.898 sec
[ INF ] At time 9.930 sec <Box algorithm::Stimulation based epoching> Still processing epoch for stimulation OVTK_StimulationId_Label_01 with timestamps 9.898 sec:9.898 sec:10.898 sec
[ INF ] At time 9.930 sec <Box algorithm::Stimulation based epoching> Chunk start time: 9.656 sec, chunk end time: 9.688 sec

From the first debug print we can assume that you select a 1 second epoch just after the stimulation.
The theoretical epoch should be 1 second long, i.e. the chunk outputed by the box should be 1 second long.
In the last debug message the difference between the chunk start time and end time is not 1 second. Are you printing the start and end time dates of the signal chunk, as I supposed ?

I did some testing with sample signal and stimulation (sinus oscillator & keyboard stimulator).
I printed the stimulation date with a Stimulation Listener and the chunk details with an EBML stream spy to get accurate start and end time of the signal chunks outputed by the Stimulation Based Epoching. The SBE is configured to produce a 1 second epoch after the stimulation Label_01, no offset.

I configured openvibe with the following tokens:

Code: Select all

Kernel_ConsoleLogTimeInSecond = False
Kernel_ConsoleLogWithHexa = True

In order to get the precise timings plus its hexadecimal value, and not just an estimate in seconds.

Here is an example of printed result in the background console:

Code: Select all

[  INF  ] At time 36507222016 <Box algorithm::Stimulation listener> For input 0 with name Stimulation stream 1 got stimulation 33025[OVTK_StimulationId_Label_01] at date 36507222016 (0x880000000) and duration 0 (0x0)
...
[WARNING] At time 42882564096 <Box algorithm::EBML stream spy> 
[WARNING] At time 42882564096 <Box algorithm::EBML stream spy> For input Spied EBML stream 1 of type EBML stream :
[WARNING] At time 42882564096 <Box algorithm::EBML stream spy> For chunk [id:0] at [time:(0x00000008, 0x80000000),(0x00000009, 0x80000000)]
[WARNING] At time 42882564096 <Box algorithm::EBML stream spy>   Opened EBML node [id:(0x00cf2101, 0x02375310)]-[name:OVTK_NodeId_Buffer]
[WARNING] At time 42882564096 <Box algorithm::EBML stream spy>     Opened EBML node [id:(0x00120663, 0x08fbc165)]-[name:OVTK_NodeId_Buffer_StreamedMatrix]
[WARNING] At time 42882564096 <Box algorithm::EBML stream spy>       Opened EBML node [id:(0x00b18c10, 0x427d098c)]-[name:OVTK_NodeId_Buffer_StreamedMatrix_RawBuffer]-[type:binary]-[bytes:65536]
[WARNING] At time 42882564096 <Box algorithm::EBML stream spy> 

We get as requested a 1 second epoch starting at time:(0x00000008, 0x80000000) = 0x880000000 = 36507222016, date of the stimulation.

This behavior is confirmed on a real data file from a P300 session.

Please let me know how your investigations are progressing.

Laurent-

[ddvlamin]

We saw that you added the 2 debug messages, the first one being already in the original source code.

I hope you don't mean with "we saw" that I accidently commited any like that?

In the last debug message the difference between the chunk start time and end time is not 1 second. Are you printing the start and end time dates of the signal chunk, as I supposed ?

Correct.

This is however the start and end times of the incoming chunks and as I understand it I think this can not be compared with the EBML spy box you connect to the output of the epoching box because there you set the begin and end time of the epoch "chunk" to the ones computed from the stimulus date which is also correct in my example. What I find strange is that At time 9.930 it is still processing incoming chunks (throwing them away) from time 9.656. I can understand this when a scenario can not achieve real-time because then the real-time will be advanced further than the time indicated in the chunks, but this does not seem to be the case here. Am I correct to assume that the time in "At time ..." is real time and not OpenViBE simulated time, while the time of the chunks come from the file or are these stamped based on OpenViBE's simulated time? I truly want to get more insight in the definitions of time and how it is used to for tagging in OpenViBE

Thanks,
Dieter

[yrenard]

Dear Dieter,

every time value that you see at the box level is simulated real time, be it acquired from a device or replayed from file. Only the application layer has real real time awareness (that is the designer and the acquisition server for instance).

Another thing to consider is that the delay between the actual stim emission and its prosessing in later boxes varies depending on the scheduling (you can inspect that at Trace level if you need when you start the scenario). The same happens when data is replayed from a file (none of the boxes or the application are aware you are replaying file instead of acquiring from the device).

Hope this helps,
Yann

[ddvlamin]

Dear Yann,

I agree and understand what you say (although not in depth as I still have some questions sorry ), but in my opinion it still does not explain the 300 ms of delay (to me 300ms is a century in computer time). The two scenarios are basically the same, one with a file reader and an epoching box and one where the file reader is replaced by a signal and stimulus generator, two very simple scenarios. Even if the scheduling differs, this should never have such a big impact in these very simple scenarios.

I however still do not understand which printed times are real and which are simulated. So

The "At time..." that comes from the LogManager is this also simulated time or real time? Assuming it is also simulated time then it should more or less correspond to the chunk time, because this is the basis for computing simulated time (number of chunks and the sample frequency give you an indication of the computed time). However this does not seem to be the case given the output above in the first example.

The chunk start times and end times must be simulated or computed time. If you read from file, are the chunk times read from the file or are they computed based on the sample frequency and the number of blocks that have been read?

I reckon that the time displayed in the designer is also simulated time as it runs slow when one can not reach real time?

Best regards,
Dieter Devlaminck

[yrenard]

Hello Dieter,

I am surprised how much these timing concerns raise questions, dicussions and explanations.
I always do my best to make it clear but it seems I still fail to do so...

I agree and understand what you say (although not in depth as I still have some questions sorry ), but in my opinion it still does not explain the 300 ms of delay (to me 300ms is a century in computer time). The two scenarios are basically the same, one with a file reader and an epoching box and one where the file reader is replaced by a signal and stimulus generator, two very simple scenarios. Even if the scheduling differs, this should never have such a big impact in these very simple scenarios.

agreed

I however still do not understand which printed times are real and which are simulated.

everything is simulated time. No box, no scenario, no player, no OpenViBE object but the app itself is aware of the real time (in this case, the app is the designer).

By the way, the fact that everything is simulated time is what permits to keep everything in sync.

The "At time..." that comes from the LogManager is this also simulated time or real time? Assuming it is also simulated time then it should more or less correspond to the chunk time, because this is the basis for computing simulated time (number of chunks and the sample frequency give you an indication of the computed time). However this does not seem to be the case given the output above in the first example.

The start/end times that are printed are, I believe, those from the signal stream, not the stims.
These two streams are independant from each other, and the box that receives both uses the start/end time to keep everything in sync.

The chunk start times and end times must be simulated or computed time. If you read from file, are the chunk times read from the file or are they computed based on the sample frequency and the number of blocks that have been read?

If you read GDF file, the timestanps are generated by the reading box.
If you read OpenViBE file, the timestamps are the ones that were received by the writing box. By the way, the chunks that get out of the reading box, gets out at the same time they got in the writing box while recording. That means if you have a 300ms or even 10 second delay when you record the file, you will have the same delay when you read it back. If you were recording the file as it came out from the acquisition client, that should not affect (much) the delay.

I reckon that the time displayed in the designer is also simulated time as it runs slow when one can not reach real time?

Yes it is.

I hope this helps,
regards,
Yann

[ddvlamin]

I am surprised how much these timing concerns raise questions, dicussions and explanations.

I'm sorry about these questions, but I guess if someone writes a new box and notices some things while debugging that are not well understood, one will try to understand what is in the black box. Sometimes it is necessary for the box developer that he has an idea on how and when inputs can arrive at the box so as to handle things properly. Maybe it's something you can write about on your blog, how the kernel calls the box, how time, signal and stimuli are managed and synchronized? I know or at least I guess it was/is your intention to hide all this for the box developer, but from time to time it think it can be useful for the developer to have more insight in this too.

Anyway thanks for answering again.

By the way, the fact that everything is simulated time is what permits to keep everything in sync.

\

That is why I do not understand why a certain box processes a signal timestamped 9.5s-9.6s for example at second 10. You would suspect that the simulated time is computed based on the chunk number and the sample frequency of the signal and thus these two timings should correspond, i.e. signal timestamped at 9.9s-10s is processed at second 10 of simulated time.

By the way, the chunks that get out of the reading box, gets out at the same time they got in the writing box while recording. That means if you have a 300ms or even 10 second delay when you record the file, you will have the same delay when you read it back

Ok this would explain the previous question.

If you were recording the file as it came out from the acquisition client, that should not affect (much) the delay.

This is confusing with what you wrote just before. You always record a new file through the acquisition server, so there should never be this kind of delay then?

Dieter

[yrenard]

Dieter, did you have any progress with this issue ?

Maybe it's something you can write about on your blog

I'd love to blog more, it's been a long time I did not post, sorry for this.

That is why I do not understand why a certain box processes a signal timestamped 9.5s-9.6s for example at second 10. You would suspect that the simulated time is computed based on the chunk number and the sample frequency of the signal and thus these two timings should correspond, i.e. signal timestamped at 9.9s-10s is processed at second 10 of simulated time.

You should look at the Generic Stream Reader box source code, and maybe the writer source code as well. This will help you understand how it works.

This is confusing with what you wrote just before. You always record a new file through the acquisition server, so there should never be this kind of delay then?

Maybe you do, I usually do, but you can also record only a selection of ERPs in an .ov file if you like. This data format is able to store any of the existing and future dataformats of OpenViBE because it does not have to be aware of their structure at all.

Regards,
Yann

[ddvlamin]

We got our algorithm to work properly without depending on the timing of certain incoming stimuli, so we avoided the problem

You should look at the Generic Stream Reader box source code, and maybe the writer source code as well. This will help you understand how it works.

Ok, will do.

Thanks,
Dieter