Scan statistics use much more memory than expected
I did this scan on the demo session.
That's a common scan at ID15 (except it is a continuous scan in there case)
loopscan(200000, 0.001, mca1, mca2) The result
1 [||||||||| 8.1%] 4 [|||| 3.7%]
2 [|||||| 4.9%] 5 [|||||| 5.6%]
3 [||||||||||| 9.9%] 6 [|||| 3.6%]
Mem[||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||14.9G/15.5G] Tasks: 165; 1 running
Swp[||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| 6.87G/9.31G] Load average: 3.46 2.51 2.08
Uptime: 07:03:20
PID USER PRI NI VIRT RES SHR S CPU% MEM% TIME+ Command
18908 valls 20 0 14.7G 11.0G 2988 S 0.0 70.9 45:28.20 /users/valls/Software/miniconda3/envs/blissenv/bin/python -m bliss.shell.cli.start_bliss_repl demo_session WARN
18663 valls 20 0 1452M 649M 2272 S 0.0 4.1 5:24.59 redis-server *:10003
18949 valls 20 0 1630M 560M 25040 S 1.2 3.5 28:29.90 /users/valls/Software/miniconda3/envs/blissenv/bin/python -m bliss.flint -s demo_session
18910 valls 20 0 1149M 419M 3700 S 0.0 2.6 18:23.57 /users/valls/Software/miniconda3/envs/blissenv/bin/python -m bliss.shell.data.start_listener demo_sessionThe memory is not release after the end of the scan.
Here is the kind of warnings i have received in the BLISS session during the scan
WARNING 2021-01-29 14:47:28,911 global.controllers.StepScanDataWatch: data watcher failed for 'mca1:ocr_det0' (Data is not anymore available first_index:28400 request_index:28300) ] 28511/200000 eta [52:13]
WARNING 2021-01-29 14:47:28,930 global.controllers.StepScanDataWatch: data watcher failed for 'mca1:deadtime_det0' (Data is not anymore available first_index:28400 request_index:28300)
WARNING 2021-01-29 14:47:28,966 global.controllers.StepScanDataWatch: data watcher failed for 'mca1:icr_det3' (Data is not anymore available first_index:28400 request_index:28300) 4
WARNING 2021-01-29 14:47:28,992 global.controllers.StepScanDataWatch: data watcher failed for 'mca2:trigger_livetime_det2' (Data is not anymore available first_index:28400 request_index:28300)
WARNING 2021-01-29 14:48:25,069 global.controllers.StepScanDataWatch: data watcher failed for 'mca1:ocr_det3' (Data is not anymore available first_index:31900 request_index:31800) 32003 0 29
WARNING 2021-01-29 14:48:25,092 global.controllers.StepScanDataWatch: data watcher failed for 'mca2:deadtime_det0' (Data is not anymore available first_index:31900 request_index:31800)
WARNING 2021-01-29 14:48:25,124 global.controllers.StepScanDataWatch: data watcher failed for 'mca2:icr_det1' (Data is not anymore available first_index:31900 request_index:31800) 6
WARNING 2021-01-29 14:48:25,173 global.controllers.StepScanDataWatch: data watcher failed for 'mca2:energy_livetime_det2' (Data is not anymore available first_index:31900 request_index:31800) 9
WARNING 2021-01-29 14:48:25,204 global.controllers.StepScanDataWatch: data watcher failed for 'mca2:triggers_det3' (Data is not anymore available first_index:31900 request_index:31800) 13 8
WARNING 2021-01-29 14:49:28,535 global.controllers.StepScanDataWatch: data watcher failed for 'mca1:realtime_det2' (Data is not anymore available first_index:35900 request_index:35800) 6010 48 36
WARNING 2021-01-29 14:49:28,573 global.controllers.StepScanDataWatch: data watcher failed for 'mca1:deadtime_det2' (Data is not anymore available first_index:35900 request_index:35800) 3
WARNING 2021-01-29 14:49:28,682 global.controllers.StepScanDataWatch: data watcher failed for 'mca2:events_det1' (Data is not anymore available first_index:35900 request_index:35800) 20
WARNING 2021-01-29 14:51:02,249 global.controllers.StepScanDataWatch: data watcher failed for 'mca2:icr_det0' (Data is not anymore available first_index:41800 request_index:41700) 41912 6 09
WARNING 2021-01-29 14:52:22,361 global.controllers.StepScanDataWatch: data watcher failed for 'mca1:energy_livetime_det0' (Data is not anymore available first_index:46900 request_index:46800) 7000 4 10
WARNING 2021-01-29 14:52:22,409 global.controllers.StepScanDataWatch: data watcher failed for 'mca1:events_det1' (Data is not anymore available first_index:46900 request_index:46800) 4
WARNING 2021-01-29 14:52:24,076 global.controllers.StepScanDataWatch: data watcher failed for 'mca1:energy_livetime_det2' (Data is not anymore available first_index:47000 request_index:46800) 113 08
WARNING 2021-01-29 14:52:24,123 global.controllers.StepScanDataWatch: data watcher failed for 'mca1:deadtime_det3' (Data is not anymore available first_index:46900 request_index:46800) 6
WARNING 2021-01-29 14:52:24,196 global.controllers.StepScanDataWatch: data watcher failed for 'mca2:realtime_det2' (Data is not anymore available first_index:47000 request_index:46800) 9
WARNING 2021-01-29 14:52:24,237 global.controllers.StepScanDataWatch: data watcher failed for 'mca2:energy_livetime_det3' (Data is not anymore available first_index:46900 request_index:46800) 23 7
WARNING 2021-01-29 14:52:24,313 global.controllers.StepScanDataWatch: data watcher failed for 'mca2:icr_det3' (Data is not anymore available first_index:47000 request_index:46800) 9
WARNING 2021-01-29 14:53:01,573 global.controllers.StepScanDataWatch: data watcher failed for 'mca1:events_det0' (Data is not anymore available first_index:49400 request_index:49300) 9500 3 15
WARNING 2021-01-29 14:53:01,663 global.controllers.StepScanDataWatch: data watcher failed for 'mca1:ocr_det1' (Data is not anymore available first_index:49400 request_index:49300) 6
WARNING 2021-01-29 14:53:01,773 global.controllers.StepScanDataWatch: data watcher failed for 'mca1:energy_livetime_det3' (Data is not anymore available first_index:49400 request_index:49300) 12 4
WARNING 2021-01-29 14:53:01,921 global.controllers.StepScanDataWatch: data watcher failed for 'mca2:triggers_det2' (Data is not anymore available first_index:49400 request_index:49300) 22
WARNING 2021-01-29 14:54:40,197 global.controllers.StepScanDataWatch: data watcher failed for 'mca1:triggers_det2' (Data is not anymore available first_index:55600 request_index:55500) 55706 1 06
WARNING 2021-01-29 14:54:40,421 global.controllers.StepScanDataWatch: data watcher failed for 'mca2:deadtime_det2' (Data is not anymore available first_index:55600 request_index:55500) 23
WARNING 2021-01-29 14:54:44,918 global.controllers.StepScanDataWatch: data watcher failed for 'timer:elapsed_time' (Data is not anymore available first_index:55612 request_index:55600) 6000 0
WARNING 2021-01-29 14:54:59,666 global.controllers.StepScanDataWatch: data watcher failed for 'mca1:energy_livetime_det1' (Data is not anymore available first_index:56800 request_index:56600) 948 0 40
WARNING 2021-01-29 14:55:00,217 global.controllers.StepScanDataWatch: data watcher failed for 'mca2:events_det3' (Data is not anymore available first_index:56800 request_index:56600) 84
WARNING 2021-01-29 14:56:22,855 global.controllers.StepScanDataWatch: data watcher failed for 'mca2:ocr_det3' (Data is not anymore available first_index:62100 request_index:61700) 62212 38 56
WARNING 2021-01-29 14:56:27,830 global.controllers.StepScanDataWatch: data watcher failed for 'mca1:realtime_det0' (Data is not anymore available first_index:62100 request_index:62000) 528 0
WARNING 2021-01-29 14:56:27,885 global.controllers.StepScanDataWatch: data watcher failed for 'mca1:triggers_det0' (Data is not anymore available first_index:62100 request_index:62000) 31
WARNING 2021-01-29 14:56:28,220 global.controllers.StepScanDataWatch: data watcher failed for 'mca1:trigger_livetime_det2' (Data is not anymore available first_index:62200 request_index:62000) 54 49
WARNING 2021-01-29 14:56:28,659 global.controllers.StepScanDataWatch: data watcher failed for 'mca2:realtime_det1' (Data is not anymore available first_index:62100 request_index:62000) 80
WARNING 2021-01-29 14:56:28,711 global.controllers.StepScanDataWatch: data watcher failed for 'mca2:energy_livetime_det1' (Data is not anymore available first_index:62200 request_index:62000) 3 8
WARNING 2021-01-29 14:56:28,762 global.controllers.StepScanDataWatch: data watcher failed for 'mca2:deadtime_det1' (Data is not anymore available first_index:62100 request_index:62000) 6
WARNING 2021-01-29 14:56:28,967 global.controllers.StepScanDataWatch: data watcher failed for 'mca2:realtime_det3' (Data is not anymore available first_index:62200 request_index:62000) 99
WARNING 2021-01-29 14:56:29,019 global.controllers.StepScanDataWatch: data watcher failed for 'mca2:trigger_livetime_det3' (Data is not anymore available first_index:62300 request_index:62000) 602
WARNING 2021-01-29 14:56:41,939 global.controllers.StepScanDataWatch: data watcher failed for 'mca1:trigger_livetime_det0' (Data is not anymore available first_index:63200 request_index:62900) 3425 32
WARNING 2021-01-29 14:56:42,274 global.controllers.StepScanDataWatch: data watcher failed for 'mca1:deadtime_det1' (Data is not anymore available first_index:63000 request_index:62900) 45
WARNING 2021-01-29 14:56:42,602 global.controllers.StepScanDataWatch: data watcher failed for 'mca1:events_det3' (Data is not anymore available first_index:63000 request_index:62900) 68 1
WARNING 2021-01-29 14:56:42,886 global.controllers.StepScanDataWatch: data watcher failed for 'mca2:trigger_livetime_det1' (Data is not anymore available first_index:63000 request_index:62900) 84
WARNING 2021-01-29 14:56:43,139 global.controllers.StepScanDataWatch: data watcher failed for 'mca2:events_det2' (Data is not anymore available first_index:63100 request_index:62900) 500
WARNING 2021-01-29 14:56:43,191 global.controllers.StepScanDataWatch: data watcher failed for 'mca2:ocr_det2' (Data is not anymore available first_index:63000 request_index:62900) 3
WARNING 2021-01-29 14:59:24,555 global.controllers.StepScanDataWatch: data watcher failed for 'mca1:triggers_det1' (Data is not anymore available first_index:73500 request_index:73200) 73738 5 17
WARNING 2021-01-29 15:00:32,180 global.controllers.StepScanDataWatch: data watcher failed for 'timer:epoch' (Data is not anymore available first_index:77509 request_index:77145) 8003 3 59
WARNING 2021-01-29 15:00:33,436 global.controllers.StepScanDataWatch: data watcher failed for 'mca2:triggers_det1' (Data is not anymore available first_index:77600 request_index:77200) 85 8
WARNING 2021-01-29 15:01:44,092 global.controllers.StepScanDataWatch: data watcher failed for 'mca2:ocr_det0' (Data is not anymore available first_index:81900 request_index:81600) 82588 2 36
WARNING 2021-01-29 15:02:15,230 global.controllers.StepScanDataWatch: data watcher failed for 'mca2:ocr_det1' (Data is not anymore available first_index:84300 request_index:83500) 4540 01
WARNING 2021-01-29 15:02:47,063 global.controllers.StepScanDataWatch: data watcher failed for 'mca2:deadtime_det3' (Data is not anymore available first_index:85600 request_index:84700) 6564 1 25
WARNING 2021-01-29 15:05:31,232 global.controllers.StepScanDataWatch: data watcher failed for 'mca2:energy_livetime_det0' (Data is not anymore available first_index:96200 request_index:95800) 96963 28 23
WARNING 2021-01-29 15:05:49,613 global.controllers.StepScanDataWatch: data watcher failed for 'mca1:trigger_livetime_det3' (Data is not anymore available first_index:98000 request_index:96900) 8125 03
WARNING 2021-01-29 15:05:49,996 global.controllers.StepScanDataWatch: data watcher failed for 'mca2:realtime_det0' (Data is not anymore available first_index:97900 request_index:96900) 47
WARNING 2021-01-29 15:07:42,628 global.controllers.StepScanDataWatch: data watcher failed for 'mca1:icr_det2' (Data is not anymore available first_index:104200 request_index:103900) 105169/2 0 6 04
WARNING 2021-01-29 15:10:08,582 global.controllers.StepScanDataWatch: data watcher failed for 'mca2:events_det0' (Data is not anymore available first_index:113900 request_index:112900) 14292 3 30
WARNING 2021-01-29 15:12:24,243 global.controllers.StepScanDataWatch: data watcher failed for 'mca2:trigger_livetime_det0' (Data is not anymore available first_index:122600 request_index:121200) 22713 1 09
WARNING 2021-01-29 15:12:46,860 global.controllers.StepScanDataWatch: data watcher failed for 'mca1:icr_det0' (Data is not anymore available first_index:122700 request_index:122500) 4131 0 46
WARNING 2021-01-29 15:12:47,168 global.controllers.StepScanDataWatch: data watcher failed for 'mca1:realtime_det1' (Data is not anymore available first_index:122600 request_index:122500) 50 5
WARNING 2021-01-29 15:14:25,800 global.controllers.StepScanDataWatch: data watcher failed for 'mca1:trigger_livetime_det1' (Data is not anymore available first_index:128900 request_index:128600) 30245 19 04
WARNING 2021-01-29 15:14:26,691 global.controllers.StepScanDataWatch: data watcher failed for 'mca1:events_det2' (Data is not anymore available first_index:128900 request_index:128700) 99
WARNING 2021-01-29 15:14:27,182 global.controllers.StepScanDataWatch: data watcher failed for 'mca1:triggers_det3' (Data is not anymore available first_index:128800 request_index:128700) 329 3
WARNING 2021-01-29 15:17:07,706 global.controllers.StepScanDataWatch: data watcher failed for 'mca1:icr_det1' (Data is not anymore available first_index:138700 request_index:138500) 40226 6 20
WARNING 2021-01-29 15:18:05,520 global.controllers.StepScanDataWatch: data watcher failed for 'mca1:ocr_det2' (Data is not anymore available first_index:142500 request_index:142000) 3764 5 22
WARNING 2021-01-29 15:32:07,972 bliss.scanning.writer.nexus: Cannot check Nexus writer scan state (Nexus writer API_DeviceTimedOut: Timeout (3000 mS) exceeded on device id00/bliss_nxwriter/demo_session, command scan_state) 02 26 After to fixes, the remaining leak of memory is the scan statistics, which can be fixed the following way:
diff --git a/bliss/common/profiling.py b/bliss/common/profiling.py
index 7a7fb2227..d39bd0127 100644
--- a/bliss/common/profiling.py
+++ b/bliss/common/profiling.py
@@ -157,7 +157,7 @@ def simple_time_profile(stats_dict, name, logger=None):
finally:
call_end = time.time()
stat = stats_dict.setdefault(name, list())
- stat.append((call_start, call_end))
+ # stat.append((call_start, call_end))
if logger is not None:
logger.debug("End %s Took %fs" % (name, call_end - call_start))