Missing events in the mwk2 file

Support
21

Hi Chris,

Sorry for the late reply. I ran the experiment on Friday using the Mworks version you sent. It ran for over an hour and a half; even though the file size is larger than before, I think the issue is still there. I have checked the stim updates and it shows a run time of 30 mins or so. I have included a link of the file for you to check. Additionally, I would like to know if I can get the time on the experiment computer from the system variable.

https://newcastle-my.sharepoint.com/:u:/g/personal/nba41_newcastle_ac_uk/EXC0SGtOnapEmgrfTIfx7GQBmZ2QlOHLSSc1A8AKA5FVXw?e=kthwlE

Cheers,
Beshoy

22

Hi Beshoy,

I have included a link of the file for you to check.

Thanks, but what I really need is the special log file: /tmp/mwserver_event_file_log.txt. It’s overwritten every time you open an event file, so unless you haven’t run any experiments since you generated the last faulty data file, I’ll need you to generate another one. Sorry for not being clearer.

Chris

23

Hi Chris,

Found it, I attached it here.

Cheers,
Beshoy

24

Attachment: mwserver_event_file_log.txt (5.15 MB)

25

Hi Beshoy,

Thanks for sending the log file. It has shed considerable light on the problem.

It appears that the data-file writing code isn’t losing track of any events, and it keeps on writing them to disk right up until the point that you close the data file. However, at some point in the experiment, the rate at which events are written falls drastically below the rate at which events are generated, producing an enormous backlog (e.g. 30 minutes or more) of events. When you tell MWorks to close the data file, the data-file writing code stops as soon as possible, and any events in the backlog are never written to disk.

So there are two problems here:

  1. At some point, something is causing the rate at which events are written to the event file to plummet.
  2. MWorks isn’t handling the backlog of unwritten events produced by problem 1.

Problem 2 is certainly fixable on my end. I’m working on that now, and I’ll get an updated build to you ASAP.

Problem 1 is a bit of a mystery. I can think of three explanations why a backlog of events might be building up:

  1. The experiment is simply generating way more events per unit time than can be written to disk in that time.
  2. The CPU is overloaded, so the data-file writing code isn’t running as often as needed.
  3. The actual writes to disk are taking an unreasonably long time.

Looking at your data file, I see no support for explanation 1. Your experiment seems to generate a perfectly reasonable number of events per unit time.

I also find explanation 2 dubious. If the CPU were really that overloaded, you would probably be noticing it in myriad ways (e.g. long application opening times, slow user interfaces). Unless that has been your experience, I’m inclined to rule this out, too.

That leaves us with explanation 3. If disk I/O is taking an exceptionally long time, then I’d expect that either

  • other processes are also doing a lot of disk I/O, causing a lot of contention and slowing things down for everyone, or
  • there’s a physical problem with the disk.

You can get a sense of the system’s disk I/O activity by opening the Activity Monitor application and switching to the “Disk” tab. If you see huge numbers by “Data read/sec” or “Data written/sec”, then that may be the underlying issue.

On the other hand, if the issue is with the health of the disk, then I’m not sure how best to diagnose that. I suppose you could try running Disk Utility’s “First Aid” procedure on it, as that may find some problems.

As I said, I’m working on a new MWorks build for you to try. In this build, I’ll include some additional logging that will hopefully clarify why the event backlog is happening. I’ll let you know as soon as I have it ready.

Thank you for your patience and assistance in debugging this issue!

Chris

26

Hi Beshoy,

The new MWorks build is ready. You can grab the installer at

As with the previous build, this one logs details of the event-file writing process to the file /tmp/mwserver_event_file_log.txt. However, the log includes more details than before.

With this build, your event files should not be missing any events. (If they are, then I’ve done something wrong.) However, there should still be an event backlog. The evidence of this will be in the server console. Upon closing the event file, two messages will be logged to the console. For example:

00:00:18:  Closing data file...
00:00:18:  Closed data file: /Users/cstawarz/Documents/MWorks/Data/test.mwk2

The crucial point is that the first message is logged before the backlog is cleared, while the second message is logged afterward. Under normal circumstances, there should be no elapsed time between the two messages (as shown above). However, in the presence of an event backlog, there will be a substantial amount of time between them (e.g. 30 minutes or more, depending on how long the experiment ran and when the backlog started).

Therefore, be sure to wait for both messages before closing MWServer. If you don’t, you will lose backlogged events (and may corrupt the event file). You may have to wait a long time, so be patient.

Please install this build on the machine that’s had data loss and try running your experiment again. If you observe an event backlog (signaled by a long delay between the two messages as described above), please send me the special log file and, if possible, the event file.

Thanks,
Chris