Thanks, cloomis.  We are already checking the logs on our side.

I've updated the frame service software on summit Gen2 to include the fix for occasional slow frame allocation. LMK from now if you experience slow allocations.

Installation time: 2023-02-09 16:00

A couple more longish ones recently. For 2023, the five out of 2415 requests which took more than 5s:

2023-04-03 13:09:41    7.521
2023-04-13 16:04:29    8.456
2023-04-17 04:24:04    6.24
2023-04-25 04:28:42   72.544
2023-04-26 01:12:32   78.298

For the 2023-07 run, so far:

2023-07-19 21:15:55 21.154
2023-07-20 01:51:06 35.0
2023-07-20 20:33:58 145.434
2023-07-21 03:53:55 120.745
2023-07-21 19:35:49 83.595
2023-07-22 02:04:43 190.612
2023-07-22 19:25:29 232.99
2023-07-23 04:40:06 211.413
2023-07-23 22:43:30 5.054
2023-07-24 01:36:57 7.844
2023-07-24 02:25:08 15.56
2023-07-24 12:39:45 7.584
2023-07-24 20:41:26 7.886
2023-07-25 00:42:21 6.915
2023-07-25 01:26:03 16.094
2023-07-25 02:35:40 19.909
2023-07-25 04:21:36 22.694
2023-07-25 05:42:38 29.027
2023-07-25 12:12:12 5.095
2023-07-25 12:36:08 6.486
2023-07-25 23:03:53 14.431

Even though the Gen2 side is tracking this themselves, I'll keep this list up to date both to allow comparing with them, and for our records.

It's too soon to close this issue, but it looks like the changes made during the 2023-07 run were fairly effective. The last two nights we had no timeouts.

I'm just reporting that "FetchVisitFromGen2(failed to get a visit number in 10s !))" occurred around 2023-12-16 11:24 (HST)

@cloomis, can you run your script that gives the times > 1s? I'm mostly interested in post-october. We had to make a few changes (again) in the code for sqlalchemy >= 2.x and I'm interested to see how things are going.

These are the ones (>= 1s) .we see on our side:

2023-10-12 22:06:03,423 | I | framesvc.py:166 (getFrames) | db allocation took 1.061 sec
2023-10-13 15:20:47,132 | I | framesvc.py:166 (getFrames) | db allocation took 1.109 sec
2023-10-14 10:26:34,241 | I | framesvc.py:166 (getFrames) | db allocation took 1.198 sec
2023-10-15 07:40:34,006 | I | framesvc.py:166 (getFrames) | db allocation took 1.230 sec
2023-10-16 06:14:37,252 | I | framesvc.py:166 (getFrames) | db allocation took 1.321 sec
2023-11-13 15:56:44,205 | I | framesvc.py:166 (getFrames) | db allocation took 1.469 sec
2023-11-13 15:56:44,205 | I | framesvc.py:166 (getFrames) | db allocation took 1.469 sec
2023-11-18 09:12:47,585 | I | framesvc.py:166 (getFrames) | db allocation took 1.032 sec
2023-11-18 23:55:00,358 | I | framesvc.py:166 (getFrames) | db allocation took 1.429 sec
2023-11-29 17:52:47,186 | I | framesvc.py:166 (getFrames) | db allocation took 1.595 sec
2023-12-14 05:33:06,939 | I | framesvc.py:166 (getFrames) | db allocation took 1.047 sec
2023-12-14 06:40:50,591 | I | framesvc.py:166 (getFrames) | db allocation took 1.105 sec
2023-12-15 17:05:55,818 | I | framesvc.py:166 (getFrames) | db allocation took 1.077 sec
2023-12-16 11:24:15,280 | I | framesvc.py:166 (getFrames) | db allocation took 37.494 sec

The one on 12-16 stands out.  Most requests are averaging < 250 ms.

That matches our list (minus your duplicate and plus a couple where the few ms to get to PFS brought the transaction > 1.0s)

Good. Still concerned about such an outlier, but it looks like as a whole timings are still going in the right direction.

Do you have any ideas about what caused the outlier?

Not yet.  Per chance, are your frame requests all coming from the same thread in the same g2cam process?

I believe so, on the thread.
There are still outliers in the 2023-12 allocations > 1s:

2023-12-14 01:51:24 1.062
2023-12-14 05:33:05 1.131
2023-12-14 06:40:49 1.135
2023-12-15 17:05:54 1.145
2023-12-16 11:23:37 37.545
2023-12-19 21:12:39 1.384
2023-12-21 20:58:51 1.34
2023-12-21 21:00:16 1.206
2023-12-21 21:05:00 1.287
2023-12-21 23:19:48 75.016
2023-12-22 03:08:43 58.98
2023-12-22 18:42:10 1.205
2023-12-22 19:01:21 1.021
2023-12-22 22:31:36 80.436
2023-12-23 01:23:20 116.709
2023-12-23 04:29:35 1.03
2023-12-23 04:43:15 1.126
2023-12-23 05:06:26 1.013
2023-12-23 06:53:23 128.693
2023-12-27 18:11:48 3.275
2023-12-27 18:13:00 1.795
2023-12-27 18:13:53 1.962
2023-12-27 18:14:47 1.245
2023-12-27 18:15:40 1.313
2023-12-27 18:16:34 1.082
2023-12-27 18:17:27 1.085
2023-12-27 18:31:39 1.149
2023-12-27 19:23:28 115.652
2023-12-28 00:29:47 25.147
2023-12-28 03:14:42 5.175
2023-12-28 05:22:38 8.18
2023-12-14 01:51:24 1.062
2023-12-14 05:33:05 1.131
2023-12-14 06:40:49 1.135
2023-12-15 17:05:54 1.145
2023-12-16 11:23:37 37.545
2023-12-19 21:12:39 1.384
2023-12-21 20:58:51 1.34
2023-12-21 21:00:16 1.206
2023-12-21 21:05:00 1.287
2023-12-21 23:19:48 75.016
2023-12-22 03:08:43 58.98
2023-12-22 18:42:10 1.205
2023-12-22 19:01:21 1.021
2023-12-22 22:31:36 80.436
2023-12-23 01:23:20 116.709
2023-12-23 04:29:35 1.03
2023-12-23 04:43:15 1.126
2023-12-23 05:06:26 1.013
2023-12-23 06:53:23 128.693
2023-12-27 18:11:48 3.275
2023-12-27 18:13:00 1.795
2023-12-27 18:13:53 1.962
2023-12-27 18:14:47 1.245
2023-12-27 18:15:40 1.313
2023-12-27 18:16:34 1.082
2023-12-27 18:17:27 1.085
2023-12-27 18:31:39 1.149
2023-12-27 19:23:28 115.652
2023-12-28 00:29:47 25.147
2023-12-28 03:14:42 5.175
2023-12-28 05:22:38 8.18
2023-12-28 20:45:37 1.668
2023-12-28 21:04:10 10.697
total: 1909 frames

By the logging I added yesterday, the slow time is happening in an SQLAlchemy commit() call, after inserts.  We are looking at instrumenting the Postgres side with some of the tools used to figure out slow operations.

We made one more change in December (slight change to flush/commit sequences).  So far on Gen2 side we see no allocations >= 1sec since December 30.  Although the number of allocations since then is not high.  Hopefully we can get a better sense during the next engineering in March.