Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Closed
2 tasks
y3rsh opened this issue May 18, 2022 · 5 comments
Closed
2 tasks

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

y3rsh opened this issue May 18, 2022 · 5 comments
Assignees
@y3rsh @mcous @nusrat813
Labels
6.0-feedback Feedback for the 6.0 release complete Completely resolved and/or verified fixed. robot-svcs Falls under the purview of the Robot Services squad (formerly CPX, Core Platform Experience).

Comments

@y3rsh
Copy link
Collaborator

y3rsh commented May 18, 2022 •
edited
Loading

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?

freezing.mov

Expected Behavior

No freezing, smooth execution of commands

expected.mov

Steps To Reproduce

#10330

  • adding magnetic module script
  • attach logs

Operating system

mac
@y3rsh y3rsh added robot-svcs Falls under the purview of the Robot Services squad (formerly CPX, Core Platform Experience). 6.0-feedback Feedback for the 6.0 release labels May 18, 2022
@mcous
Copy link
Contributor

mcous commented May 18, 2022

@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
Copy link
Collaborator Author

y3rsh commented May 18, 2022

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
Copy link
Collaborator Author

y3rsh commented May 19, 2022 •
edited
Loading

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
Copy link
Collaborator Author

y3rsh commented May 19, 2022

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

@y3rsh y3rsh closed this as completed May 19, 2022
@y3rsh y3rsh added the complete Completely resolved and/or verified fixed. label May 19, 2022
@SyntaxColoring SyntaxColoring mentioned this issue May 19, 2022
Merged
@SyntaxColoring
Copy link
Contributor

SyntaxColoring commented May 19, 2022 •
edited
Loading

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.

This was referenced May 19, 2022
Closed
Merged
@SyntaxColoring SyntaxColoring mentioned this issue Jun 25, 2022
Merged
2 tasks
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@y3rsh y3rsh

@mcous mcous

@nusrat813 nusrat813

Labels
6.0-feedback Feedback for the 6.0 release complete Completely resolved and/or verified fixed. robot-svcs Falls under the purview of the Robot Services squad (formerly CPX, Core Platform Experience).
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@y3rsh @mcous @SyntaxColoring @nusrat813