Mesoscope ophys frame rate is incorrect for recent experiments

[alexpiet]

Describe the bug
Here I am describing what I believe is one bug (possibly related to #1753, #1751, ), and a separate issue concerning three mice. I am not sure if the issues are actually separate, so I am reporting them as one issue.

1. The BehaviorOphysSession.metadata['ophys_frame_rate'] for mesoscope should be ~11hz. However for most experiments it is 43.0. Note that this is ~4x the expected rate, so this is probably related to issues Mesoscope ophys timestamps improperly truncated #1753, Traces may not be the same length as ophys_timestamps for BehaviorOphysSession #1751. Scientifica experiments return the expected ~31hz.

   Small note possibly related to the other linked issues. I expect the last timestamp to be ~4500s since that is the length of the session. For scientifica session.ophys_timestamps[-1] is about that value. However for mesoscope the last timestamp is about ~1130, consistent with the 4x truncation mentioned in the other issues.

2. There are some experiments on mesoscope that have a different ophys_frame_rate. This is very concerning because most of these experiments are new, and I'm worried a setting got changed in active data collection. Issue (1) seems like an SDK issue, but this could be a data collection problem.

   This is not an exclusive list. These sessions/experiments were found by my GLM code crashing. There could be more.
   specimen_ids = [900263316, 1022744256, 1028194415]
ophys_session_ids = [962045676, 1048363441,1050231786,1051107431,1051319542,1052096166,1052512524,1052752249, 10429240847,1050929040,1052330675]

   2a) Specimen_id = 900263316, has one ophys_session_id = 962045676 with this problem (that I found). All of its 8 ophys_experiment_ids report having an ophys_frame_rate of 21.

   2b) Specimen_id = [1022744256, 1028194415], have ophys_frame_rate = 37.
   Both of these mice were recorded in Sept. 2020, have experiment_workflow_state =passed, and are Vip-IRES-Cre. They both have project_code = VisualBehaviorMultiscope

To Reproduce
We can check the ophys frame rate either from the metadata, or by asking the median timestamp difference:

from allensdk.brain_observatory.behavior.behavior_ophys_session import BehaviorOphysSession
session = BehaviorOphysSession.from_lims(ophys_experiment_id)
print(session.metadata['ophys_frame_rate'] )
print(1/np.median(np.diff(session.ophys_timestamps)))

Expected behavior

1. For mesoscope sessions, I expect the ophys_frame_rate and median timestamp difference to be ~11hz, instead of ~43 hz. For scientifica I expect this number to be 31hz (current correct for scientifica).

2. I expect all the mesoscope sessions to have the same ophys_frame_rate. I am very concerned that these new mice have the wrong sample rate that doesnt appear to be an obvious issue like the 4x issue for all the mesoscope mice. We need to quickly determine at what sampling rate the data was collected.

Environment (please complete the following information):

• OS & version: CentOs
• Python version: 3. 7
• AllenSDK version: current as of 10/21/

@matchings @nataliaorlova

[dougollerenshaw]

Here's a self-contained code block that will convert the ophys_session_id that @alexpiet provided above to ophys_experiment_id. As Alex stated above, the expected value of the print statements in this code block is 11 Hz.

from allensdk.brain_observatory.behavior.behavior_ophys_session import BehaviorOphysSession
import visual_behavior.database as db
import numpy as np

ophys_session_id = 1052330675
query = 'select ID from ophys_experiments where ophys_session_id = {} limit 1'
ophys_experiment_id = db.lims_query(query.format(ophys_session_id))
session = BehaviorOphysSession.from_lims(ophys_experiment_id)
print(session.metadata['ophys_frame_rate'] )
print(1/np.median(np.diff(session.ophys_timestamps)))

37.0
36.536353671878196

[alexpiet]

Checking for more bad containers by:
mice_to_check = experiments.query('(equipment_name in ["MESO.1"])&(project_code in ["VisualBehaviorMultiscope", "VisualBehaviorMultiscope4areasx2d"])').sort_values(by='date_of_acquisition')['specimen_id'].unique()

Additional specimen_ids with this problem:
specimen_id = 1024040327
ophys_session_id = 1043687843
ophys_experiment_id = 1043854205
session_type = OPHYS_1

Working backwards in time, the next-previous mouse looks to be ok at 43 Hz

[nataliaorlova]

The 1) sounds like a problem of not recording the "split" frame-rate as an experiment frame-rate. 43 is the correct value for overall frame rate, before it is resampled.
The 2) sounds to me like a (pretty bad) acquisition error. I would have to look at the raw data' metadata to see why the numbers are so different.

[kschelonka]

Thanks Alex. Affirming that the ophys timestamps ending at 1300 instead of 4500 is indeed a known bug (#1753).

The calculation of ophys frame rate is via the timestamps:

        ophys_timestamps = self.get_ophys_timestamps()
        return np.round(1 / np.mean(np.diff(ophys_timestamps)), 0)

I'm surprised to see that the frame rate is 43 Hz... It shouldn't be sensitive to the truncation (see above). I wonder if it's possible that the plane group was null for some reason (so the data weren't split). I will investigate.

[kschelonka]

@dougollerenshaw I ran your snippet and got

9.0
9.132420091324448

Have you upgraded to Allensdk 2.3.2? (2.3 contained the ophys time splitting update, but has not yet fixed the standing truncation bug #1753)

[alexpiet]

@kschelonka You are right, I thought I was on the current master (2.3.2), but I think I hadn't restarted my terminal. This looks like it resolves issue (1), but not issue (2) above. Sorry!

Edit: I confirmed that I still see issue (2). Specimen_id = [1024040327,1022744256, 1028194415] all have ophys_frame_rate =9, instead of the expected 11.

[dougollerenshaw]

@kschelonka I was an 1.8.0. I'm now on 2.3.2 and I get the same numbers as you (9.0, 9.132420091324448) when running the code block I pasted above.

[nataliaorlova]

@alexpiet , @kschelonka the issue 2 is the change on the acquisition side due to some hardware settings change. We will discuss it today/tomorrow with the stakeholders, meanwhile set the frame rate to be back to 10.7 Hz

[alexpiet]

@nataliaorlova Thanks for figuring that out. It will be important to follow up on that with stakeholders, but it doesnt seem like an SDK issue at this point.

Unless I'm mistaken there are no remaining SDK issues.
(1) was my fault for not being current on the SDK
(2) was a change in data acquisition.

I'll close this issue.