search

Opentrons / opentrons

Software for writing protocols and running them on the Opentrons Flex and Opentrons OT-2
https://opentrons.com
Apache License 2.0
425 stars 179 forks source link

6.0 Feedback: Unexpected freezing of execution during enqueued commands #10333

Closed y3rsh closed 2 years ago

y3rsh commented 2 years ago

Overview

When running a script #10330 to move to well there are unexpected freezes where the command does not execute or complete immediately as expected.

Intermittent

Current Behavior

Unexpected freezes of enqueued commands. I may have seen evidence of this in calibrations seeming sluggish?

https://user-images.githubusercontent.com/502770/169142789-1041f884-f827-4c2d-a1b9-7c972f85b88a.mov

Expected Behavior

No freezing, smooth execution of commands

https://user-images.githubusercontent.com/502770/169142816-f8f45800-7ee2-48b5-b934-b88cb5e45707.mov

Steps To Reproduce

10330

Operating system

mac

mcous commented 2 years ago

@y3rsh have you noticed any sort of consistency in how long the freeze lasts, when you are able to reproduce it? In the video attached it was 20 seconds, and looked to be in the middle of two commands.

Also, was there any client making requests to the DUT when it froze?

y3rsh commented 2 years ago

I found in the logs where there is a gap. It does not happen every run but this query seems to be the place where the freeze occurs.

May 18 21:39:23 kansas uvicorn[19851]: INFO:      - "POST /runs/b6fc26da-b53e-4b7f-849e-8aa283a8b14e/commands?waitUntilComplete=true HTTP/1.1" 201 Created
May 18 21:39:52 kansas opentrons-api[19851]: BEGIN (implicit)
May 18 21:39:52 kansas opentrons-api[19851]: SELECT run.id, run.created_at, run.protocol_id, run.state_summary, run.commands, run.engine_status, run._updated_at
                                             FROM run
                                             WHERE run.id = ?
May 18 21:39:52 kansas opentrons-api[19851]: [cached since 1304s ago] ('b6fc26da-b53e-4b7f-849e-8aa283a8b14e',)
y3rsh commented 2 years ago

I believe the above issue is now solved but I saw a similar pause during a run of my commands when the app made the below queries

May 19 13:11:29 kansas uvicorn[231]: INFO:      - "GET /runs/83444c08-aad5-4e1e-81f9-942a7edc3b4d HTTP/1.1" 200 OK
May 19 13:11:29 kansas uvicorn[231]: INFO:      - "GET /runs/83444c08-aad5-4e1e-81f9-942a7edc3b4d/commands?pageLength=1 HTTP/1.1" 200 OK
May 19 13:11:29 kansas uvicorn[231]: INFO:      - "GET /runs/83444c08-aad5-4e1e-81f9-942a7edc3b4d/commands?cursor=0&pageLength=60 HTTP/1.1" 200 OK

May 19 13:10:59 kansas uvicorn[231]: INFO:      - "POST /runs/8ee796d8-61d3-4856-8312-793dee96ee20/commands?waitUntilComplete=true HTTP/1.1" 201 Created
May 19 13:11:24 kansas uvicorn[231]: INFO:      - "GET /pipettes HTTP/1.1" 200 OK
May 19 13:11:24 kansas uvicorn[231]: INFO:      - "GET /calibration/tip_length HTTP/1.1" 200 OK
May 19 13:11:25 kansas opentrons-api[231]: BEGIN (implicit)
May 19 13:11:25 kansas opentrons-api[231]: SELECT run.id, run.protocol_id, run.created_at
                                           FROM run
                                           WHERE run.id = ?
May 19 13:11:25 kansas opentrons-api[231]: [cached since 285.2s ago] ('83444c08-aad5-4e1e-81f9-942a7edc3b4d',)
May 19 13:11:25 kansas opentrons-api[231]: SELECT action.id, action.created_at, action.action_type, action.run_id
                                           FROM action
                                           WHERE action.run_id = ?
May 19 13:11:25 kansas opentrons-api[231]: [cached since 285.2s ago] ('83444c08-aad5-4e1e-81f9-942a7edc3b4d',)
May 19 13:11:25 kansas opentrons-api[231]: COMMIT
May 19 13:11:25 kansas opentrons-api[231]: BEGIN (implicit)
May 19 13:11:25 kansas opentrons-api[231]: SELECT run.state_summary
                                           FROM run
                                           WHERE run.id = ?
May 19 13:11:25 kansas opentrons-api[231]: [cached since 285.2s ago] ('83444c08-aad5-4e1e-81f9-942a7edc3b4d',)
May 19 13:11:25 kansas opentrons-api[231]: COMMIT
May 19 13:11:25 kansas opentrons-api[231]: BEGIN (implicit)
May 19 13:11:25 kansas opentrons-api[231]: SELECT run.commands
                                           FROM run
                                           WHERE run.id = ?
May 19 13:11:25 kansas opentrons-api[231]: [cached since 284.7s ago] ('83444c08-aad5-4e1e-81f9-942a7edc3b4d',)
May 19 13:11:25 kansas opentrons-api[231]: COMMIT
May 19 13:11:25 kansas opentrons-api[231]: BEGIN (implicit)
May 19 13:11:25 kansas opentrons-api[231]: SELECT run.commands
                                           FROM run
                                           WHERE run.id = ?
May 19 13:11:25 kansas opentrons-api[231]: [cached since 284.7s ago] ('83444c08-aad5-4e1e-81f9-942a7edc3b4d',)
May 19 13:11:25 kansas opentrons-api[231]: COMMIT
May 19 13:11:25 kansas uvicorn[231]: INFO:      - "GET /runs/83444c08-aad5-4e1e-81f9-942a7edc3b4d HTTP/1.1" 200 OK
May 19 13:11:25 kansas uvicorn[231]: INFO:      - "GET /runs/83444c08-aad5-4e1e-81f9-942a7edc3b4d/commands?pageLength=1 HTTP/1.1" 200 OK
May 19 13:11:25 kansas uvicorn[231]: INFO:      - "GET /runs/83444c08-aad5-4e1e-81f9-942a7edc3b4d/commands?cursor=0&pageLength=60 HTTP/1.1" 200 OK
May 19 13:11:28 kansas uvicorn[231]: INFO:      - "GET /health HTTP/1.1" 200 OK
May 19 13:11:29 kansas uvicorn[231]: INFO:      - "GET /pipettes HTTP/1.1" 200 OK
May 19 13:11:29 kansas uvicorn[231]: INFO:      - "GET /calibration/tip_length HTTP/1.1" 200 OK
May 19 13:11:29 kansas opentrons-api[231]: BEGIN (implicit)
May 19 13:11:29 kansas opentrons-api[231]: SELECT run.id, run.protocol_id, run.created_at
                                           FROM run
                                           WHERE run.id = ?
May 19 13:11:29 kansas opentrons-api[231]: [cached since 289.4s ago] ('83444c08-aad5-4e1e-81f9-942a7edc3b4d',)
May 19 13:11:29 kansas opentrons-api[231]: SELECT action.id, action.created_at, action.action_type, action.run_id
                                           FROM action
                                           WHERE action.run_id = ?
May 19 13:11:29 kansas opentrons-api[231]: [cached since 289.4s ago] ('83444c08-aad5-4e1e-81f9-942a7edc3b4d',)
May 19 13:11:29 kansas opentrons-api[231]: COMMIT
May 19 13:11:29 kansas opentrons-api[231]: BEGIN (implicit)
May 19 13:11:29 kansas opentrons-api[231]: SELECT run.state_summary
                                           FROM run
                                           WHERE run.id = ?
May 19 13:11:29 kansas opentrons-api[231]: [cached since 289.4s ago] ('83444c08-aad5-4e1e-81f9-942a7edc3b4d',)
May 19 13:11:29 kansas opentrons-api[231]: COMMIT
May 19 13:11:29 kansas opentrons-api[231]: BEGIN (implicit)
May 19 13:11:29 kansas opentrons-api[231]: SELECT run.commands
                                           FROM run
                                           WHERE run.id = ?
May 19 13:11:29 kansas opentrons-api[231]: [cached since 288.9s ago] ('83444c08-aad5-4e1e-81f9-942a7edc3b4d',)
May 19 13:11:29 kansas opentrons-api[231]: COMMIT
May 19 13:11:29 kansas opentrons-api[231]: BEGIN (implicit)
May 19 13:11:29 kansas opentrons-api[231]: SELECT run.commands
                                           FROM run
                                           WHERE run.id = ?
May 19 13:11:29 kansas opentrons-api[231]: [cached since 288.9s ago] ('83444c08-aad5-4e1e-81f9-942a7edc3b4d',)
May 19 13:11:29 kansas opentrons-api[231]: COMMIT
May 19 13:11:29 kansas uvicorn[231]: INFO:      - "GET /runs/83444c08-aad5-4e1e-81f9-942a7edc3b4d HTTP/1.1" 200 OK
May 19 13:11:29 kansas uvicorn[231]: INFO:      - "GET /runs/83444c08-aad5-4e1e-81f9-942a7edc3b4d/commands?pageLength=1 HTTP/1.1" 200 OK
May 19 13:11:29 kansas uvicorn[231]: INFO:      - "GET /runs/83444c08-aad5-4e1e-81f9-942a7edc3b4d/commands?cursor=0&pageLength=60 HTTP/1.1" 200 OK
May 19 13:11:30 kansas opentrons-api-serial[231]: smoothie: Write -> b'M907 A0.8 B0.3 C0.3 X0.3 Y0.3 Z0.1 G4 P0.005 G0 A127.002 \r\n\r\n'
May 19 13:11:30 kansas opentrons-api-serial[231]: smoothie: Read <- b'ok\r\nok\r\n'
May 19 13:11:30 kansas opentrons-api-serial[231]: smoothie: Write -> b'M400 \r\n\r\n'
May 19 13:11:30 kansas opentrons-api-serial[231]: smoothie: Read <- b'ok\r\nok\r\n'
May 19 13:11:30 kansas opentrons-api-serial[231]: smoothie: Write -> b'M907 A0.1 B0.3 C0.3 X1.25 Y1.25 Z0.1 G4 P0.005 G0 X190.985 Y51.193 \r\n\r\n'
May 19 13:11:30 kansas opentrons-api-serial[231]: smoothie: Read <- b'ok\r\nok\r\n'
May 19 13:11:30 kansas opentrons-api-serial[231]: smoothie: Write -> b'M400 \r\n\r\n'
May 19 13:11:30 kansas opentrons-api-serial[231]: smoothie: Read <- b'ok\r\nok\r\n'
May 19 13:11:30 kansas opentrons-api-serial[231]: smoothie: Write -> b'M907 A0.8 B0.3 C0.3 X0.3 Y0.3 Z0.1 G4 P0.005 G0 A117.95 \r\n\r\n'
May 19 13:11:30 kansas opentrons-api-serial[231]: smoothie: Read <- b'ok\r\nok\r\n'
May 19 13:11:30 kansas opentrons-api-serial[231]: smoothie: Write -> b'M400 \r\n\r\n'
May 19 13:11:30 kansas opentrons-api-serial[231]: smoothie: Read <- b'ok\r\nok\r\n'
May 19 13:11:30 kansas uvicorn[231]: INFO:      - "POST /runs/8ee796d8-61d3-4856-8312-793dee96ee20/commands?waitUntilComplete=true HTTP/1.1" 201 Created
May 19 13:11:31 kansas opentrons-api-serial[231]: smoothie: Write -> b'M907 A0.8 B0.3 C0.3 X0.3 Y0.3 Z0.1 G4 P0.005 G0 A132.002 \r\n\r\n'
May 19 13:11:31 kansas opentrons-api-serial[231]: smoothie: Read <- b'ok\r\nok\r\n'
May 19 13:11:31 kansas opentrons-api-serial[231]: smoothie: Write -> b'M400 \r\n\r\n'
May 19 13:11:31 kansas opentrons-api-serial[231]: smoothie: Read <- b'ok\r\nok\r\n'
May 19 13:11:31 kansas opentrons-api-serial[231]: smoothie: Write -> b'M907 A0.1 B0.3 C0.3 X1.25 Y1.25 Z0.1 G4 P0.005 G0 X147.076 Y259.388 \r\n\r\n'
May 19 13:11:31 kansas opentrons-api-serial[231]: smoothie: Read <- b'ok\r\nok\r\n'```
y3rsh commented 2 years ago

Closing, if the most recent comment is an issue it will be another ticket.

SyntaxColoring commented 2 years ago

This was worked around in a quick way in #10340. The underlying cause remains unclear. Further work to identify the underlying cause and maybe roll some of these changes back is ticketed as #10353.