Packet handler running too long exec_time: 3 warning? #249

slowrunner · 2022-11-21T23:57:58Z

slowrunner
Nov 21, 2022

Are these "Packet handler running too long" warnings expected?

Nov 21 20:22:04 tb4create3 user.notice create-platform: [INFO] [1669062124.658963552] [system_health]: CPU usage: max 66 [%] mean 63 [%] RAM usage: 25/59 [MB]
Nov 21 20:23:04 tb4create3 user.notice create-platform: [INFO] [1669062184.659175089] [system_health]: CPU usage: max 63 [%] mean 58 [%] RAM usage: 25/59 [MB]
Nov 21 20:24:04 tb4create3 user.notice create-platform: [INFO] [1669062244.662181871] [system_health]: CPU usage: max 59 [%] mean 54 [%] RAM usage: 25/59 [MB]
Nov 21 20:25:04 tb4create3 user.notice create-platform: [INFO] [1669062304.663872112] [system_health]: CPU usage: max 59 [%] mean 55 [%] RAM usage: 25/59 [MB]
Nov 21 20:26:04 tb4create3 user.notice create-platform: [INFO] [1669062364.661637281] [system_health]: CPU usage: max 59 [%] mean 53 [%] RAM usage: 26/59 [MB]
Nov 21 20:27:04 tb4create3 user.notice create-platform: [INFO] [1669062424.661106574] [system_health]: CPU usage: max 60 [%] mean 56 [%] RAM usage: 26/59 [MB]
Nov 21 20:27:24 tb4create3 user.notice ntpd: Script called in periodic mode
Nov 21 20:28:04 tb4create3 user.notice create-platform: [INFO] [1669062484.662002713] [system_health]: CPU usage: max 60 [%] mean 54 [%] RAM usage: 26/59 [MB]
Nov 21 20:29:04 tb4create3 user.notice create-platform: [INFO] [1669062544.662660399] [system_health]: CPU usage: max 59 [%] mean 54 [%] RAM usage: 26/59 [MB]
Nov 21 20:30:04 tb4create3 user.notice create-platform: [INFO] [1669062604.663237199] [system_health]: CPU usage: max 60 [%] mean 54 [%] RAM usage: 26/59 [MB]
Nov 21 20:30:04 tb4create3 user.notice create-platform: 3  id: 25
Nov 21 20:30:04 tb4create3 user.notice create-platform: [WAR] Packet handler running too long exec_time: 3  id: 25
Nov 21 20:30:04 tb4create3 user.notice create-platform: [WAR] Packet handler running too long exec_time: 3  id: 90
Nov 21 20:30:04 tb4create3 user.notice create-platform: [WAR] Packet handler running too long exec_time: 3  id: 25
Nov 21 20:30:04 tb4create3 user.notice create-platform: [WAR] Packet handler running too long exec_time: 3  id: 90
Nov 21 20:30:04 tb4create3 user.notice create-platform: [WAR] Packet handler running too long exec_time: 3  id: 25
Nov 21 20:30:04 tb4create3 user.notice create-platform: [WAR] Packet handler running too long exec_time: 3  id: 25
Nov 21 20:30:04 tb4create3 user.notice create-platform: [WAR] Packet handler running too long exec_time: 3  id: 25
Nov 21 20:30:04 tb4create3 user.notice create-platform: [WAR] Packet handler running too long exec_time: 3  id: 25
Nov 21 20:30:04 tb4create3 user.notice create-platform: [WAR] Packet handler running too long exec_time: 3  id: 25
Nov 21 20:30:04 tb4create3 user.notice create-platform: [WAR] Packet handler running too long exec_time: 3  id: 18
Nov 21 20:30:04 tb4create3 user.notice create-platform: [WAR] Packet handler running too long exec_time: 3  id: 18
Nov 21 20:30:04 tb4create3 user.notice create-platform: [WAR] Packet handler running too long exec_time: 3  id: 25
Nov 21 20:30:04 tb4create3 user.notice create-platform: [WAR] Packet handler running too long exec_time: 3  id: 25
Nov 21 20:30:04 tb4create3 user.notice create-platform: [WAR] Packet handler running too long exec_time: 4  id: 90
Nov 21 20:30:04 tb4create3 user.notice create-platform: [WAR] Packet handler running too long exec_time: 3  id: 18
Nov 21 20:30:04 tb4create3 user.notice create-platform: [WAR] Packet handler running too long exec_time: 3  id: 25
Nov 21 20:30:04 tb4create3 user.notice create-platform: [WAR] Packet handler running too long exec_time: 4  id: 18
Nov 21 20:30:15 tb4create3 user.notice ntpd: ntpd: timed out waiting for 192.168.186.1, reach 0x00, next query in 539s
Nov 21 20:31:04 tb4create3 user.notice create-platform: [WAR] Packet handler running too long exec_time: [INFO] [1669062664.666691970] [system_health]: CPU usage: max 59 [%] mean 55 [%] RAM usage: 25/59 [MB]
Nov 21 20:32:04 tb4create3 user.notice create-platform: [INFO] [1669062724.664120572] [system_health]: CPU usage: max 64 [%] mean 54 [%] RAM usage: 25/59 [MB]
Nov 21 20:33:04 tb4create3 user.notice create-platform: [INFO] [1669062784.664719233] [system_health]: CPU usage: max 60 [%] mean 55 [%] RAM usage: 25/59 [MB]
Nov 21 20:34:04 tb4create3 user.notice create-platform: [INFO] [1669062844.664654781] [system_health]: CPU usage: max 62 [%] mean 54 [%] RAM usage: 25/59 [MB]
Nov 21 20:34:38 tb4create3 user.notice create-platform: [INFO] [1669062878.250384302] [motion_control]: Received new undock goal
Nov 21 20:34:38 tb4create3 user.notice create-platform: [INFO] [1669062878.291789996] [motion_control]: digital_sensor_msi_listener: m_is_config_active 1
Nov 21 20:34:43 tb4create3 user.notice create-platform: [INFO] [1669062883.781290895] [motion_control]: Undock Goal Succeeded
Nov 21 20:34:43 tb4create3 user.notice create-platform: [INFO] [1669062883.844170609] [motion_control]: digital_sensor_msi_listener: m_is_config_active 0
Nov 21 20:35:04 tb4create3 user.notice create-platform: [INFO] [1669062904.665819502] [system_health]: CPU usage: max 61 [%] mean 56 [%] RAM usage: 25/59 [MB]
Nov 21 20:36:04 tb4create3 user.notice create-platform: [INFO] [1669062964.668423445] [system_health]: CPU usage: max 57 [%] mean 52 [%] RAM usage: 25/59 [MB]
Nov 21 20:37:04 tb4create3 user.notice create-platform: [INFO] [1669063024.669371226] [system_health]: CPU usage: max 60 [%] mean 56 [%] RAM usage: 25/59 [MB]
Nov 21 20:38:04 tb4create3 user.notice create-platform: [INFO] [1669063084.667243106] [system_health]: CPU usage: max 61 [%] mean 56 [%] RAM usage: 25/59 [MB]
Nov 21 20:38:25 tb4create3 user.notice ntpd: Script called in periodic mode
Nov 21 20:39:04 tb4create3 user.notice create-platform: [INFO] [1669063144.667096295] [system_health]: CPU usage: max 61 [%] mean 53 [%] RAM usage: 25/59 [MB]
Nov 21 20:39:32 tb4create3 user.notice ntpd: ntpd: timed out waiting for 192.168.186.1, reach 0x00, next query in 540s
Nov 21 20:40:04 tb4create3 user.notice create-platform: [INFO] [1669063204.668027656] [system_health]: CPU usage: max 59 [%] mean 54 [%] RAM usage: 25/59 [MB]
Nov 21 20:41:04 tb4create3 user.notice create-platform: [INFO] [1669063264.674500336] [system_health]: CPU usage: max 59 [%] mean 55 [%] RAM usage: 25/59 [MB]
Nov 21 20:42:04 tb4create3 user.notice create-platform: [INFO] [1669063324.671639443] [system_health]: CPU usage: max 65 [%] mean 62 [%] RAM usage: 25/59 [MB]
Nov 21 20:42:15 tb4create3 user.notice mosquitto: 1669063335: New connection from 127.0.0.1 on port 1883.
Nov 21 20:42:15 tb4create3 user.notice mosquitto: 1669063335: New client connected from 127.0.0.1 as mosqpub/24351-tb4create (c1, k60).
Nov 21 20:42:15 tb4create3 user.notice mosquitto: 1669063335: Client mosqpub/24351-tb4create disconnected.

and again later:

Nov 21 23:23:04 tb4create3 user.notice create-platform: [INFO] [1669072984.759493695] [system_health]: CPU usage: max 66 [%] mean 60 [%] RAM usage: 25/59 [MB]
Nov 21 23:24:01 tb4create3 user.notice create-platform: [INFO] [1669073041.265762356] [mobility_monitor]: Received mobility notification: ROBOT_NOTIFY_CHARGE_COMPLETE (84) with arg 108
Nov 21 23:24:04 tb4create3 user.notice create-platform: [INFO] [1669073044.759817565] [system_health]: CPU usage: max 66 [%] mean 57 [%] RAM usage: 25/59 [MB]
Nov 21 23:24:50 tb4create3 user.notice ntpd: Script called in periodic mode
Nov 21 23:25:04 tb4create3 user.notice create-platform: [INFO] [1669073104.760653131] [system_health]: CPU usage: max 57 [%] mean 53 [%] RAM usage: 25/59 [MB]
Nov 21 23:26:04 tb4create3 user.notice create-platform: [INFO] [1669073164.762885763] [system_health]: CPU usage: max 57 [%] mean 53 [%] RAM usage: 25/59 [MB]
Nov 21 23:27:04 tb4create3 user.notice create-platform: [INFO] [1669073224.764427804] [system_health]: CPU usage: max 60 [%] mean 53 [%] RAM usage: 25/59 [MB]
Nov 21 23:27:10 tb4create3 user.notice ntpd: ntpd: timed out waiting for 192.168.186.1, reach 0x00, next query in 518s
Nov 21 23:28:04 tb4create3 user.notice create-platform: [INFO] [1669073284.761473533] [system_health]: CPU usage: max 60 [%] mean 54 [%] RAM usage: 25/59 [MB]
Nov 21 23:29:04 tb4create3 user.notice create-platform: [INFO] [1669073344.763087211] [system_health]: CPU usage: max 59 [%] mean 53 [%] RAM usage: 25/59 [MB]
Nov 21 23:30:04 tb4create3 user.notice create-platform: [INFO] [1669073404.762512751] [system_health]: CPU usage: max 57 [%] mean 52 [%] RAM usage: 26/59 [MB]
Nov 21 23:31:04 tb4create3 user.notice create-platform: [INFO] [1669073464.765878389] [system_health]: CPU usage: max 58 [%] mean 55 [%] RAM usage: 26/59 [MB]
Nov 21 23:32:04 tb4create3 user.notice create-platform: [INFO] [1669073524.766524785] [system_health]: CPU usage: max 56 [%] mean 52 [%] RAM usage: 26/59 [MB]
Nov 21 23:33:04 tb4create3 user.notice create-platform: [INFO] [1669073584.767619581] [system_health]: CPU usage: max 61 [%] mean 53 [%] RAM usage: 26/59 [MB]
Nov 21 23:34:04 tb4create3 user.notice create-platform: [INFO] [1669073644.764813327] [system_health]: CPU usage: max 61 [%] mean 54 [%] RAM usage: 25/59 [MB]
Nov 21 23:35:04 tb4create3 user.notice create-platform: [INFO] [1669073704.765832162] [system_health]: CPU usage: max 58 [%] mean 53 [%] RAM usage: 25/59 [MB]
Nov 21 23:35:38 tb4create3 user.notice create-platform: [INFO] [1669073738.865052267] [motion_control]: Received new undock goal
Nov 21 23:35:38 tb4create3 user.notice create-platform: -24 meas_vel:0,0
Nov 21 23:35:38 tb4create3 user.notice create-platform: [DBG] RobotDock constructor
Nov 21 23:35:38 tb4create3 user.notice create-platform: [DBG] dock_statemachine: sent docking params packet initial pass
Nov 21 23:35:38 tb4create3 user.notice create-platform: [DBG] robot_dock_statemachine: DOCK_PROTO_SEND_CONFIG -->> DOCK_PROTO_WAIT_CONFIG
Nov 21 23:35:38 tb4create3 user.notice create-platform: [DBG] robot_dock: got config received
Nov 21 23:35:38 tb4create3 user.notice create-platform: [DBG] start msi::MotionControlBehavior::DOCKING: dock
Nov 21 23:35:38 tb4create3 user.notice create-platform: [DBG] robot_dock_statemachine: DOCK_PROTO_WAIT_CONFIG -->> DOCK_PROTO_RUNNING
Nov 21 23:35:38 tb4create3 user.notice create-platform: [DBG] dock_statemachine: mob behavior started!
Nov 21 23:35:38 tb4create3 user.notice create-platform: [DBG] [SE]: !velocity_stopped - cmd_vel:23,-23 meas_vel:0,0
Nov 21 23:35:38 tb4create3 user.notice create-platform: [DBG] dock_statemachine: mobility behavior stopped running!
Nov 21 23:35:38 tb4create3 user.notice create-platform: [DBG] robot_dock_statemachine: DOCK_PROTO_RUNNING -->> DOCK_PROTO_GET_STATUS
Nov 21 23:35:38 tb4create3 user.notice create-platform: [DBG] robot_dock: got status back
Nov 21 23:35:38 tb4create3 user.notice create-platform: [DBG] robot_dock_statemachine: DOCK_PROTO_GET_STATUS -->> DOCK_PROTO_WAIT_DONE
Nov 21 23:35:38 tb4create3 user.notice create-platform: [DBG] robot_dock: timed out packet response
Nov 21 23:35:38 tb4create3 user.notice create-platform: [DBG] stop BEHAVIOR_DOCKING 0
Nov 21 23:35:38 tb4create3 user.notice create-platform: [WAR] Packet handler running too long exec_time: 3  id: 90
Nov 21 23:35:38 tb4create3 user.notice create-platform: [WAR] Packet handler running too long exec_time: 3  id: 25
Nov 21 23:35:38 tb4create3 user.notice create-platform: [DBG] RobotDock constructor
Nov 21 23:35:38 tb4create3 user.notice create-platform: [DBG] undock_statemachine: sent docking params packet initial pass
Nov 21 23:35:38 tb4create3 user.notice create-platform: [DBG] robot_undock_statemachine: [INFO] [1669073738.887232251] [motion_control]: digital_sensor_msi_listener: m_is_config_active 1
Nov 21 23:35:44 tb4create3 user.notice create-platform: [INFO] [1669073744.330733242] [motion_control]: Undock Goal Succeeded
Nov 21 23:35:44 tb4create3 user.notice create-platform: [INFO] [1669073744.389892809] [motion_control]: digital_sensor_msi_listener: m_is_config_active 0
Nov 21 23:35:50 tb4create3 user.notice ntpd: Script called in periodic mode
Nov 21 23:36:04 tb4create3 user.notice create-platform: [INFO] [1669073764.765849384] [system_health]: CPU usage: max 59 [%] mean 55 [%] RAM usage: 25/59 [MB]
Nov 21 23:36:05 tb4create3 user.notice ntpd: ntpd: timed out waiting for 192.168.186.1, reach 0x00, next query in 521s
Nov 21 23:37:04 tb4create3 user.notice create-platform: [INFO] [1669073824.768167962] [system_health]: CPU usage: max 61 [%] mean 55 [%] RAM usage: 25/59 [MB]
Nov 21 23:38:04 tb4create3 user.notice create-platform: [INFO] [1669073884.769783164] [system_health]: CPU usage: max 63 [%] mean 54 [%] RAM usage: 25/59 [MB]
Nov 21 23:39:04 tb4create3 user.notice create-platform: [INFO] [1669073944.768661568] [system_health]: CPU usage: max 59 [%] mean 54 [%] RAM usage: 25/59 [MB]

Version G.3.1

Answered by alsora

Nov 22, 2022

These warnings are mostly meant for iRobot developers to help us debugging issues.

They indicate that some operations are taking more time than expected (the exec time is in milliseconds).
They are not a problem on their own, especially if you only have a handful of occurrences.

If a user is experiencing problems with its robot, it's important to check for these logs to determine if some tasks are being starved.
In your case, you can safely ignore them.

View full answer

alsora · 2022-11-22T00:09:52Z

alsora
Nov 22, 2022
Maintainer

These warnings are mostly meant for iRobot developers to help us debugging issues.

They indicate that some operations are taking more time than expected (the exec time is in milliseconds).
They are not a problem on their own, especially if you only have a handful of occurrences.

If a user is experiencing problems with its robot, it's important to check for these logs to determine if some tasks are being starved.
In your case, you can safely ignore them.

0 replies

slowrunner · 2023-12-12T00:29:41Z

slowrunner
Dec 12, 2023
Author

closing - answered and stale issue.

0 replies

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Packet handler running too long exec_time: 3 warning? #249

{{title}}

{{editor}}'s edit

{{editor}}'s edit

Replies: 2 comments

{{title}}

{{title}}

Select a reply

Packet handler running too long exec_time: 3 warning? #249

slowrunner Nov 21, 2022

Replies: 2 comments

alsora Nov 22, 2022 Maintainer

slowrunner Dec 12, 2023 Author

slowrunner
Nov 21, 2022

alsora
Nov 22, 2022
Maintainer

slowrunner
Dec 12, 2023
Author