Improve ASI detector support and reduce excessive logging

[Baharis]

The context

This week I worked on adapting Instamatic to our ASI Medipix3 detector via the CameraServal class. Despite variety of issues, many of them boiled to the same problems. Actions listed below led to GUI crashing:

1. Setting exposure > 10 seconds;
2. Setting exposure ≤ 0 seconds;
3. Collecting any images other than the preview;
4. Starting the GUI with default config.

AD 1 & 2, I learned to my surprise that both ASI Medipix3 and Timepix3 impose hard limits on exposure: >0, ≤10 seconds. I have therefore added a validate method to CameraServal that trims any exposure passed to a [0.001, 10] range and logs a warning. If anything requests 20-second frame, it will receive a 10-second frame after approx. 10.2 seconds. It is neither pretty nor general but it gets the job done and fixes 99% of issues.

EDIT: After reviewing and consulting this issue, instead of trimming the values to the limits, I have implemented a way to collect <0 and >10 second exposures. The former returns empty images, the latter sums shorter frames collected via a re-implemented get_movie. I also synchronized CameraServal.get_image and get_movie and removed an issue with GUI freezing at exit. For more details, see this comment.

AD 3, In #108, I addressed 0-second preview crashing the GUI. Since then I learned that even if exposure > 0, the GUI itself sometimes requests 0-second images. This happens because VideoSteram.get_image starts by setting self.grabber.frametime = 0 to "prevent it lagging data acquisition" and does some stuff, but before self.grabber.acquireInitiateEvent.set(), the ImageGraber.run in 2nd thread races to self.cam.get_image and often manages to call it – with frametime=0. I found that replacing self.grabber.frametime set/restore with self.block()/unblock() achieves the same effect while never requesting a dreaded 0-second image.

AD 4, As for why the default config fails, the "cooldown" between exposures is hard-coded to 0.5ms. In fact, it should be higher if using Timepix3 asic or "PixelDepth": 24. On his fork, @hzanoli suggests using different hard-coded values based on a new config parameter asic but I believe a more elegant solution is to derive it from the difference between initial ExposureTime and TriggerPeriod.

Furthermore. I noticed that for "PixelDepth": 24, the preview was much smoother than for "PixelDepth": 12. After some tests I realized that in 12-bit mode, data was passed as pgm and in 24-bit – as tiff (also enforced for Timepix3 asic by @hzanoli). I tested pgm and tiff and found out that reading tiff with Pillow was significantly faster. So here I ask: why even use pgm in the first place (benchmark code)?

file_format                pgm             png            tiff
bit_depth                                                    
1             117.41 ± 6.32 ms   nan ±  nan ms  0.17 ± 0.03 ms
4            117.24 ± 11.10 ms   nan ±  nan ms  0.17 ± 0.04 ms
6            151.23 ± 48.35 ms   nan ±  nan ms  0.16 ± 0.01 ms
8              0.08 ±  0.22 ms  1.41 ± 0.09 ms  0.20 ± 0.07 ms
10           153.95 ± 13.69 ms   nan ±  nan ms  0.63 ± 0.10 ms
12           153.15 ± 23.07 ms   nan ±  nan ms  0.46 ± 0.17 ms
14           150.50 ± 17.25 ms   nan ±  nan ms  0.68 ± 0.11 ms
16             1.84 ±  0.20 ms  2.10 ± 0.15 ms  0.42 ± 0.15 ms
20              nan ±   nan ms   nan ±  nan ms  2.17 ± 0.22 ms
24              nan ±   nan ms   nan ±  nan ms  2.21 ± 0.21 ms
32              nan ±   nan ms   nan ±  nan ms  2.22 ± 0.19 ms

When debugging, I was trying to use instamatic log but it was extremely inconvenient because currently it captures every debug message from every package. Unrelevant debug messages, mostly from PIL, are generated in an absurd rate: ~2000 if running instamatic for 12 seconds, ~100 MB / hour. So here I suggest modifying GUI file handler so that:

• Instamatic logger.debug messages are logged only if at least -v is set;
• Imported library debug statements are logged only if at least -vv is set;
• Log messages include whole file path instead of just module name if -vvv is set.

Finally, during my tests I noticed that some of the links were outdated or wrong. I was also disappointed I could not copy-and-paste Instamatic citation. So I changed that: looks slightly different but CTRL+C works!

Major changes

• CameraServal: Derive the length of cooldown period between exposures from config (trigger - exposure) rather than using a hard-coded value;
• CameraServal: Hard-limit exposure times between 0.001 and 10 seconds;
• EDIT: CameraServal: If requested exposure equal or lower than 0, return an empty array.
• EDIT: CameraServal: If requested exposure >10, return sum of images from re-implemented get_movie.
• instamatic/main.py (GUI): Limit log size from ~100 MB/h to KB/h by not-logging debug messages unless a new flag -v (for insamatic) for -vv (for imported libraries) is specified.

Minor changes

• VideoStream.get_image: Use block() instead of frametime=0 to temporarily pause the preview.
• CameraServal: Send images in tiff rather than significantly-slower-to-decode pgm.
• EDIT: CameraServal: Re-implement get_movie, synchronize it with get_image to prevent errors.
• serval.yaml: Add comments, update values to work for ASI Timepix3 (credit: @hzanoli);
• AboutFrame: Fix links and make author & reference fields select-and-copy-able.

Bugfixes

• cred/experiment.py: Allow using simulated FEI camera (credit: @hzanoli);
• camera_serval.py: Remove unused import statements;
• AboutFrame: Fix __main__ so that it can be shown stand-alone if ever desired;
• THANKS.md: Fix the link so that it points to the correct contributors list;
• EDIT: gui.py: on close(), redirect sys.stdout and sys.stderr back so that it does not freeze GUI;
• EDIT: tem_server.py: make imports global to facilitate running via main / instamatic.temserver.

Effect on the codebase

Using ASI detectors in instamatic should now work and shouldn't randomly crash at every chance. I analyzed the code and successfully ran some RED (!), and I think replacing framerate=0 with block() should be fine, but arguably I do now know if it does not affect something I did not touch. Likewise with pgm: I don't understand why it was used in the first place, it is not faster. I do not believe anyone will miss debug logs from external libraries, but importantly now -v is needed to see instamatic debug messages as well.

[Baharis]

@hzanoli , @ErikHogenbirkASI Could you kindly confirm that both Medipix3 and Timepix3 allow for exposures greater than 0 and lower/equal than 10? This is what I found in both documentations.

[Baharis]

@ErikHogenbirkASI Do you remember how you determined that pgm is faster than tiff? My PIL benchmark suggests it is much slower, especially if the bit depth is not 2**N i.e. in this case.

file_format                pgm             png            tiff
bit_depth                                                    
1             117.41 ± 6.32 ms   nan ±  nan ms  0.17 ± 0.03 ms
4            117.24 ± 11.10 ms   nan ±  nan ms  0.17 ± 0.04 ms
6            151.23 ± 48.35 ms   nan ±  nan ms  0.16 ± 0.01 ms
8              0.08 ±  0.22 ms  1.41 ± 0.09 ms  0.20 ± 0.07 ms
10           153.95 ± 13.69 ms   nan ±  nan ms  0.63 ± 0.10 ms
12           153.15 ± 23.07 ms   nan ±  nan ms  0.46 ± 0.17 ms
14           150.50 ± 17.25 ms   nan ±  nan ms  0.68 ± 0.11 ms
16             1.84 ±  0.20 ms  2.10 ± 0.15 ms  0.42 ± 0.15 ms
20              nan ±   nan ms   nan ±  nan ms  2.17 ± 0.22 ms
24              nan ±   nan ms   nan ±  nan ms  2.21 ± 0.21 ms
32              nan ±   nan ms   nan ±  nan ms  2.22 ± 0.19 ms

[Baharis]

@hzanoli This PR addresses the same issues as your fork. If I understand everything correctly, it makes the asic config addition unnecessary since tiff becomes the new default file format and exposure cooldown is dynamically determined from existing fields. I believe your Timepix3 clients should now be able to use instamatic on the new main branch, whether they applied the config changes you suggested or not.

[stefsmeets]

Nice work, looks good to me. Glad that you are willing to debug the serval integration.

Let me know when this is ready to merge.

[stefsmeets]

I wonder if this call is not going to be too spammy. I'd say it's also fair to raise a ValueError here.

Suggested change

	exposure = self._validate_exposure(exposure)
	if not (0.001 < exposure < 10):
	raise ValueError('Exposure must be between 0.001 and 10 s')

[Baharis]

While this would be a more elegant approach, unfortunately this error is something I am specifically trying to avoid. Serval toolkit already does raise a RuntimeError and specifically describes in the error message that exposure must be in this range; However, the moment any error is raised here (and this can be done completely by accident e.g. when changing exposure in preview), the GUI dies. I discovered the 0-second exposure because trying to get any images other than preview caused this. If you don't like this approach, I can try tomorrow to make a precise try-except statement here instead.

[stefsmeets]

I'd say let Serval handle the data validation, but then the error must be caught at a higher level. No need to do data validation twice. You want to avoid the function invisibly updating the exposure, that's why it is better to raise.

If it's related to the gui, perhaps the gui call to this function can be behind a try/except. I think it is mainly the lower limit that causes issues in practice. Perhaps the number input in the gui could have a lower limit (exposure must be > 0). I think this makes sense in general.

[Baharis]

@stefsmeets The upper limit is also causing exceptions, and in places other than GUI. The other day I was testing flatfield algorithm and it requested 370-second exposure. I came to conclusion that instead of piling up try/except statements, I could actually implement exposures of = 0 seconds or > 10 seconds by summing images from get_movie. This will be accompanied with appropriate warning but IMO will be more general than arbitrary cut-off. I will convert this PR to draft while I am working on it.

[stefsmeets]

See comment above about raising a ValueError instead.

Suggested change

	exposure = self._validate_exposure(exposure)
	if not (0.001 < exposure < 10):
	raise ValueError('Exposure must be between 0.001 and 10 s')

[hzanoli]

@hzanoli , @ErikHogenbirkASI Could you kindly confirm that both Medipix3 and Timepix3 allow for exposures greater than 0 and lower/equal than 10? This is what I found in both documentations.

Yes. We enforce 0 < Exposure Time <=10s for both Medipix3 and Timepix3 on Serval as described in the manual.

[hzanoli]

I think it is a nice idea to derive the cooldown/deadtime to avoid having an asic field. But since that might not be very transparent to the user, I think that it deserves a small comment here, something like:

# TriggerPeriod and ExposureTime are used to derive the deadtime/cooldown of the detector.
# Please verify in the manual since different TriggerMode and other detector configurations
# require different deadtimes. 

[Baharis]

Currently SOFTWARESTART_TIMERSTOP is the only trigger mode that I managed to get working with Instamatic. I briefly tested AUTOTRIGSTART_TIMERSTOP which massively improves the fps because it does not wait for a /measurement/start, but it is not handled by Instamatic yet (sent data can not be opened by Pillow/tifffile) so I will need to take a closer look at it in the future. For the purpose of collecting "movies" (hypothetical/untested), Instamatic sets trigger mode to CONTINUOUS, but also disregards "cooldown" and uses the same value for ExposureTime and TriggerPeriod so it will comply with Serval requirements.

I definitely like the idea of placing additional comment in the yaml file so that a user can make a conscious choice about setting ExposureTime and TriggerPeriod. I will base and possibly expand it on your suggestion. Thank you!

[Baharis]

Observation regarding pgm versus tiff

@ErikHogenbirkASI, @emx77 Concerning the pgm versus tiff performance, I repeated my benchmark on the Windows 10 machine that runs Instamatic in the lab and it confronted them with my aforementioned tests on Windows 11. For good measure, I have also directly tested on images received by Serval toolkit from Serval server. Exact numbers below.

From what I gathered, Pillow used to handle pgm files much faster but since PR #6119, images whose max value is not 2**8 or 2**16 are scaled up to these respective values instead. Here is a script you can run to confirm this. This is very undesired when the absolute values of individual pixels actually matter, much more than the fact that processing takes longer.

What I guess happened from the development POV is that in the original code @ErikHogenbirkASI favored pgm because they were smaller (faster transfer) and their processing time was comparable/better than tiff. However, with the changes being requested in the last 3 years, the benefit of having smaller pgm files might have became overshadowed by changes in their handling by Pillow. This inadvertently led to me advertising for tiff over pgm.

I now see the drawback of using tiff: in a 12-bit mode, pgm files are indeed 4x smaller than their tiff counterpart. Indeed, assuming 1 Gb/s a transfer of 16 or 32-bit tiff file should take 4 or 8 ms, and it is worth to try to shorten it down to 1 or 2 ms. However, IMO this can not be done at the cost of changing the scale or processing for half a second.

Benchmark results

Windows 11, Python 3.13, PIL 11.1.0, AMD Ryzen 7 PRO 8840HS, 3.3Ghz, 64 GB RAM (1000 samples):

file_format                pgm             png            tiff
bit_depth                                                    
1             117.41 ± 6.32 ms   nan ±  nan ms  0.17 ± 0.03 ms
4            117.24 ± 11.10 ms   nan ±  nan ms  0.17 ± 0.04 ms
6            151.23 ± 48.35 ms   nan ±  nan ms  0.16 ± 0.01 ms
8              0.08 ±  0.22 ms  1.41 ± 0.09 ms  0.20 ± 0.07 ms
10           153.95 ± 13.69 ms   nan ±  nan ms  0.63 ± 0.10 ms
12           153.15 ± 23.07 ms   nan ±  nan ms  0.46 ± 0.17 ms
14           150.50 ± 17.25 ms   nan ±  nan ms  0.68 ± 0.11 ms
16             1.84 ±  0.20 ms  2.10 ± 0.15 ms  0.42 ± 0.15 ms
20              nan ±   nan ms   nan ±  nan ms  2.17 ± 0.22 ms
24              nan ±   nan ms   nan ±  nan ms  2.21 ± 0.21 ms
32              nan ±   nan ms   nan ±  nan ms  2.22 ± 0.19 ms

Windows 10, Python 3.12, PIL ?, Intel Core i7-2600, 3.4GHz, 16 GB RAM (100 samples):

file_format                pgm             png            tiff
bit_depth                                 
8               0.42 ± 2.08 ms  2.71 ± 0.07 ms  0.44 ± 0.04 ms
10           423.82 ± 12.52 ms    nan ± nan ms  1.18 ± 0.07 ms
12            422.33 ± 9.23 ms    nan ± nan ms  1.14 ± 0.04 ms
14            414.75 ± 9.90 ms    nan ± nan ms  1.12 ± 0.12 ms
16              2.75 ± 0.10 ms  4.32 ± 0.16 ms  0.89 ± 0.24 ms
20                nan ± nan ms    nan ± nan ms  3.30 ± 0.14 ms
24                nan ± nan ms    nan ± nan ms  3.31 ± 0.14 ms
32                nan ± nan ms    nan ± nan ms  3.30 ± 0.13 ms

Windows 10, same setup but processing actual experimental files received by serval toolkit (100 samples):

file_format                pgm            tiff
bit_depth                                 
12           430.80 ± 15.55 ms  2.40 ± 4.83 ms
24                nan ± nan ms  4.45 ± 0.25 ms

[Baharis]

Regarding the last point of controversy revolving around the exposure limits enforced by Serval, I read your suggestions @stefsmeets but I politely disagree. Allowing CameraServal to raise exceptions there or wrapping every cam.get_image in try/except are both riddled with issues. get_image methods are called in 77 places, some of them in GUI and some outside. In places, the exposure can be also calculated dynamically, meaning that even if we ourselves care not to exceed the limit, Instamatic might decide otherwise.

Instead of trying to prevent this 8-year-old who cannot swim from swimming, I taught him how to swim. After discussion with Erik Maddox, from ASI I split the CameraServal implementation of get_image into three:

• If exposure <= 0, call _get_image_null: returns a zero-array of detector shape and int32 data type;
• If exposure in limits, call _get_image_single: original trigger implementation of @ErikHogenbirkASI;
• If exposure > 10, call get_movie: a new algorithm that collects a series of images; then sums them.

The existing implementation of get_movie could theoretically work in vacuum but only in 12-bit mode (in practice it did not, see below). It also handled data as pmg, which as we now know could have every image arbitrarily scaled up. I re-implemented get_movie so that now it uses autotrigger and tiff. Auto-trigger unfortunately leaves 0.5–2 ms gaps per each 10 seconds of exposure, meaning ~0.01% of data gets lost. I added a scaling mechanism and a logger.warning to counter and warn user about this tiny effect.

I found that the existing implementation of get_movie could have worked only if camera streaming was turned off. Otherwise, initializing camera starts streaming in a second thread, meaning get_image is called every 50 ms. If you then call get_movie in the main thread, one or many racing issues can happen:

• get_image attempts to write into existing images of get_movie or vice versa, causing error;
• get_movie switches mode to CONTINUOUS (trigger-less) and get_image starts trigger, causing error;
• get_movie finished but does not restore config, get_image starts in the wrong mode causing Error; etc.

The new implementation also suffered from multiple instances of get_image running at the same time affecting to each other. To solve this issue, I "synchronized" i.e. put a lock on CameraServal methods that interact with Serval to prevent them from sending conflicting requests interchangeably.

While debugging the new implementation, I had a (dis)pleasure to realize that adding print statements to the code running in second thread caused the GUI to freeze on exit. To be precise, it took me some hours to realize print could be responsible, it is the last thing you suspect. I discovered that because sys.stdout and sys.stderr were being redirected to GUI (main thread), when the GUI was destroyed but second thread called print or raise any error, if would indefinitely wait for the response from the main thread. I fixed that by reverting the redirect in on_close, so now freezes at program exit should become far less common :).

By the time I re-open this PR for review/merge, I will have edited the initial message to reflect these changes.

[Baharis]

One more thing that I considered suggesting was disabling by default instamatic debug statement, allowing instamatic debug statement if -v, and allowing all statement if -vv. To the best of my understanding, debug statement are not something that a log should be collecting in normal conditions. I do not want to cause a revolution though.

[stefsmeets]

There is some performance penalty to logging. This is why I tried to limit logging as much as possible in the performance critical loops (data collection), to avoid unnecessary locks or interruptions.

[Baharis]

Ok, I think your opinion aligns with my suggestion. If Instamatic debug statements are logged only if -v is specified (and external debug statements only if -vv) then it becomes fine to put debug statements even in "critical loops". Which in my opinion is the correct way to go, because with this change the "critical loops" remain fast if instamatic is run as normal, but can be easily investigated if -v is specified.

For reference, according to simple search instamatic currently does not have particularly much logging, but there seems to be a healthy split between debug that I suggest to omit by default and info that I suggest to always show:

• 74 debug statements (including some in Merlin/Serval data collection loop, auto-cred, serialED, img conversion),
• 100 info statements (same files, plus more in microscope interfaces)
• 22 warn(ing) statements (joel microscope, camera merlin, comera serval, mrc format, simulation...)
• 2 error statements.

I will have that implemented today and ask for a re-review afterwards.

[stefsmeets]

Regarding the last point of controversy revolving around the exposure limits enforced by Serval, I read your suggestions @stefsmeets but I politely disagree. Allowing CameraServal to raise exceptions there or wrapping every cam.get_image in try/except are both riddled with issues. get_image methods are called in 77 places, some of them in GUI and some outside. In places, the exposure can be also calculated dynamically, meaning that even if we ourselves care not to exceed the limit, Instamatic might decide otherwise.

Fair enough, I don't want to get in the way of unnecessarily limiting the code. I'm happy with the solution you suggested. Let me know if the PR is ready and I will do a review.

[Baharis]

Alright, I modified my proposition as to how logging should be handled. With the current code changes:

• Instamatic logger.debug messages are logged only if at least -v is set;
• Imported library debug statements are logged only if at least -vv is set;
• Log messages include whole file path instead of just module name if -vvv is set.

This means that e.g. logger.debug(response) when receiving any Merlin command response or self.logger.debug(f'Image variance: {imgvar}') at each step of AutoCRED crystal tracking will not be written by GUI unless it is run with -v, and debug logs from other libraries like __init__:47 | DEBUG | Creating converter from 7 to 5 won't be written unless it is run as -vv.

As a showcase of how this new system is adaptable, and because even with -vv I had no idea what external loggers are trying to tell me, by adding a single line to the code I also made it so that if -vvv, the message contains full path of logger instead of module only, which lets one learn that the particular message raised from __init__ is, in fact, produced by matplotlib: C:\Path\To\My\instamatic\venv\Lib\site-packages\h5py\__init__.py:47 | DEBUG | Creating converter from 7 to 5.

In my opinion the PR is ready to be merged, however I do not mind waiting a few days more for suggestions. Ultimately, since it by default removes instamatic debug messages from the log, I guess there might be feedback against it.