collecting nexus-writer metadata twice makes scan slower than needed
I had a look at the logs of a small scan and I saw that the metadata collection in def device_info
(nexus_writer_service/subscribers/scan_writer_publish.py) is called twice per scan producing an unnecessary overhead.
seems like it is called at the beginning of the scan and at the end of the scan again, while as far as I can see it is sufficient to only call it once at the beginning of the scan.
DEMO_SESSION [1]: debugon("bliss.scans")
Setting bliss.scans to show debug messages
DEMO_SESSION [2]: loopscan(1,.1)
INFO 2020-11-02 16:39:15,890 bliss.scans: Doing loopscan
ERROR: reading lima property saturated_cblevel (Exception: Accumulation threshold plugins not loaded)
DEBUG 2020-11-02 16:39:16,025 bliss.scans: Start scan.init.chain
DEBUG 2020-11-02 16:39:16,025 bliss.scans: End scan.init.chain Took 0.000235s
DEBUG 2020-11-02 16:39:16,025 bliss.scans: Start scan.init.saving
DEBUG 2020-11-02 16:39:16,027 bliss.scans: End scan.init.saving Took 0.001992s
DEBUG 2020-11-02 16:39:16,027 bliss.scans: Start scan.init.display
DEBUG 2020-11-02 16:39:16,034 bliss.scans: End scan.init.display Took 0.006802s
DEBUG 2020-11-02 16:39:16,034 bliss.scans: Start scan.init.scan_info
DEBUG 2020-11-02 16:39:16,035 bliss.scans: End scan.init.scan_info Took 0.000694s
DEBUG 2020-11-02 16:39:16,035 bliss.scans: Start scan.init.writer
DEBUG 2020-11-02 16:39:16,114 bliss.scans: End scan.init.writer Took 0.079414s
DEBUG 2020-11-02 16:39:16,115 bliss.scans: Start scan.init.flint
DEBUG 2020-11-02 16:39:16,116 bliss.scans: End scan.init.flint Took 0.000974s
DEBUG 2020-11-02 16:39:16,116 bliss.scans: Start scan.prepare.node
DEBUG 2020-11-02 16:39:16,209 bliss.scans: Start scan.prepare.user_scan_meta
########## collecting device information for nexuswriter
DEBUG 2020-11-02 16:39:16,306 bliss.scans: End scan.prepare.user_scan_meta Took 0.096918s
DEBUG 2020-11-02 16:39:16,311 bliss.scans: End scan.prepare.node Took 0.194934s
DEBUG 2020-11-02 16:39:16,311 bliss.scans: Start scan.run.start_data_watcher
DEBUG 2020-11-02 16:39:16,312 bliss.scans: End scan.run.start_data_watcher Took 0.001065s
DEBUG 2020-11-02 16:39:16,325 bliss.scans: Start timer.wait_ready
...
DEBUG 2020-11-02 16:39:16,817 bliss.scans: Start scan.events.device
DEBUG 2020-11-02 16:39:16,820 bliss.scans: End scan.events.device Took 0.002984s
DEBUG 2020-11-02 16:39:16,824 bliss.scans: Start scan.fill_metadata
DEBUG 2020-11-02 16:39:16,826 bliss.scans: End scan.fill_metadata Took 0.002208s
DEBUG 2020-11-02 16:39:16,826 bliss.scans: Start scan.prepare.user_scan_meta
########## collecting device information for nexuswriter
DEBUG 2020-11-02 16:39:16,882 bliss.scans: End scan.prepare.user_scan_meta Took 0.055974s
DEBUG 2020-11-02 16:39:16,958 bliss.scans: Start scan.preset._stop
DEBUG 2020-11-02 16:39:16,958 bliss.scans: End scan.preset._stop Took 0.000201s
DEBUG 2020-11-02 16:39:16,959 bliss.scans: Start scan.finalize_writer
DEBUG 2020-11-02 16:39:16,963 bliss.scans: End scan.finalize_writer Took 0.003973s
Out [2]: Scan(number=6, name=loopscan, path=/tmp/scans/inhouse/id002011/id00/sample/sample_0002/sample_0002.h5)
DEMO_SESSION [3]:
this should help to reduce the overhead per scan. I guess the overhead could be reduced further if the loop in def device_info(scan):
would spawn several greenlets as tasks.
This is linked with #2246 and may helps to reduce the overhead reported in #2252 (closed) (edit: no metadata collection for ct...)
Edited by Linus Pithan