log events timing with millisecond-precision

[Jonathan Ye]

Dear Lex,

I am wondering if you could help us out on this printing issue with FED3 logdata() function.

I have been trying to log the timing of events in millisecond precisions by printing out existing variables "pelletTime", "leftPokeTime", or "rightPokeTime" (see codes below). 

if (Event == "Pellet"){
    logfile.print(pelletTime); // print pellet timing
  }
  else if ((Event == "Left") or (Event == "LeftShort") or (Event == "LeftWithPellet")) {
    logfile.print(leftPokeTime); // print left poke timing
  }
  else if ((Event == "Right") or (Event == "RightShort") or (Event == "RightWithPellet")) {
     logfile.print(rightPokeTime); // print left poke timing
  }
 else {
    logfile.print(sqrt (-1)); // print NaN
  } 
 logfile.print(",");

After a few manual trials, the tabulated CSV results are quite puzzling.

For example, the time elapse calculated from "Time" (1st column) does not always match the range of "Time_elapse".

There is also "decrement" in one case.

How does it happen? Could you help me with this? Thank you so much for your generous time and help.

Best,

Jonathan (Jiahao)

[Lex Kravitz]

Hi Jonathan!

Cool you're digging into the code and making FED3 do new things!

However, I don't think "pelletTime", "leftPokeTime", and "rightPokeTime" are going to be useful here.  The biggest issue is that these variables rely on the millis() function, which counts milliseconds since the device booted up, but the millis() timer does not run while the device is sleeping.  So while sleep modes are active on FED3 "pelletTime", "leftPokeTime", and "rightPokeTime" will not have a great relationship to the time on the real-time clock (RTC), which continues to count even when the device sleeps.  So where you see ~3 second passing between rows 1 and 2 of your screengrab, but only ~1.2s by millis(), or ~7 seconds passing between rows 2 and 3 but only ~3s by millis(), this is because the millis() timer stops when FED3 sleeps.

You can try turning off sleep.  But I suspect you still don't want to use these variables for timing. The "pelletTime" variable notes when the pellet drops, which is defined as when the FED3 first detects the pellet on each drop.  pelletTime is later used to calculate the "Retrieval_Time" (time from pellet drop to retrieval) in the data file.  The data is not logged until the mouse takes the pellet, which usually happens a couple seconds after "pelletTime".  This is why the value decrements in your second example - you first logged the time of a left poke (9027ms, but again remember this isn't really the time since startup, this is the time the processor was awake since startup), then a pellet dispensed at 10737ms, setting the "pelletTime" variable but not logging it because the pellet was not removed yet, then you logged another left poke time (LeftWithPellet at 12069ms).  And finally, when you removed the pellet you got the orginal pelletTime back (10737ms).  It's confusing, but the main take home may be that these variables are likely not going to get you what you want.  There are ways to use the RTC with the millis() timer to achieve millisecond precision, but I haven't had time to implement this on FED3 (there are lots of possible solutions posted for how to do this online, it should be possible on FED3 but it's not trivial). 

One simple way that may work for your needs is to turn off sleep and then just log millis() with each row of data in your "Time_elapse" column.  From a battery life perspective it's not ideal to turn off sleep but it's not awful, you should still get >3 days of battery life from a fully charged battery.  And if this works it may be a step towards working out a more complicated method for recording timing with millisecond precision while also maintaining sleep functionality.

Hope this helps make things make sense - please post back if you have any updates!  Best, -Lex