search

Elucidation / mapf-multiagent-robot-planning

Multi-Agent PathFinding (MAPF) for 2D Robots moving inventory on a grid - Practice building environment + robots + planning + inventory management etc.
MIT License
10 stars 3 forks source link

Use msgpack or similar instead of json.dumps/loads #108

Closed Elucidation closed 1 year ago

Elucidation commented 1 year ago

Note, nodejs will need the library to read it from the DB too

Elucidation commented 1 year ago

JSON

PS C:\Users\sam\Documents\GitHub\mapf-multiagent-robot-planning\dev> python -m world_sim reset
2023-06-26 10:04:14,046 - world_sim - INFO - Connecting to redis server localhost:6379
2023-06-26 10:04:14,212 - world_sim - INFO - World Shape: (94, 51), 536 robots, 504 item zones, 326 stations
Resetting database
2023-06-26 10:04:14,214 - database_world_manager - WARNING - Resetting redis Robots/State
----
2023-06-26 10:04:14,537 - world_sim - INFO - World start: T = 0, DT = 1.0
2023-06-26 10:04:14,538 - world_sim - INFO - Main loop start...
2023-06-26 10:04:14,642 - world_sim - INFO - Step 1 - took 104.732 ms
2023-06-26 10:04:15,642 - world_sim - INFO - Step 2 - took 104.105 ms
2023-06-26 10:04:16,597 - world_sim - INFO - Step 3 - took 58.041 ms
2023-06-26 10:04:17,603 - world_sim - INFO - Step 4 - took 62.822 ms
2023-06-26 10:04:18,601 - world_sim - INFO - Step 5 - took 59.773 ms
2023-06-26 10:04:19,605 - world_sim - INFO - Step 6 - took 63.645 ms
2023-06-26 10:04:20,632 - world_sim - INFO - Step 7 - took 88.894 ms
2023-06-26 10:04:21,607 - world_sim - INFO - Step 8 - took 63.025 ms
2023-06-26 10:04:22,608 - world_sim - INFO - Step 9 - took 63.539 ms
2023-06-26 10:04:23,603 - world_sim - INFO - Step 10 - took 57.756 ms
Timer unit: 1e-07 s

Total time: 0.725573 s
File: C:\Users\sam\Documents\GitHub\mapf-multiagent-robot-planning\dev\world_sim.py
Function: step at line 211

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
   211                                               @profile2
   212                                               def step(self) -> bool:
   213                                                   # For every robot in environment, pop an action and apply it
   214                                                   # check that final state has no robots colliding with walls or
   215                                                   # each other
   216        10      24061.0   2406.1      0.3          self.logger.debug('Step start')
   217        10        170.0     17.0      0.0          t_start = time.perf_counter()
   218        10        136.0     13.6      0.0          self.last_step_start_time = t_start
   219
   220        10    3860780.0 386078.0     53.2          self.robots = self.wdb.get_robots()
   221
   222        10      99656.0   9965.6      1.4          state_changed = self.step_robots()
   223
   224        10     327674.0  32767.4      4.5          self.world_state = self._check_valid_state()
   225        10         61.0      6.1      0.0          self.t += 1
   226
   227        10         23.0      2.3      0.0          if state_changed:
   228                                                       self.wdb.update_robots(self.robots)
   229
   230        10     120687.0  12068.7      1.7          self.wdb.update_timestamp(self.t)
   231
   232        10         74.0      7.4      0.0          update_duration_ms = (time.perf_counter() - t_start)*1000
   233
   234        10       5476.0    547.6      0.1          self.logger.debug(
   235        30        356.0     11.9      0.0              f'Step end, took {update_duration_ms:.3f} ms: '
   236        30         81.0      2.7      0.0              f'T={self.t} VALID={self.world_state} state change={state_changed}')
   237        10         59.0      5.9      0.0          if update_duration_ms > self.dt_sec*1000:
   238                                                       self.logger.error(
   239                                                           f'update took {update_duration_ms:.2f} > {self.dt_sec*1000} ms')
   240                                                   # Log state of world (t and robot info) to DB
   241        10        326.0     32.6      0.0          time_to_next_step_sec = self.get_time_to_next_step_s()
   242        10    1657950.0 165795.0     22.9          json_data = self.state_dict(time_to_next_step_sec)
   243        10    1158130.0 115813.0     16.0          self.wdb.log_world_state(json_data)
   244                                                   # Return if any robot has moved or not
   245        10         34.0      3.4      0.0          return state_changed

msgpack

PS C:\Users\sam\Documents\GitHub\mapf-multiagent-robot-planning\dev> python -m world_sim reset
2023-06-26 09:58:38,946 - world_sim - INFO - Connecting to redis server localhost:6379
2023-06-26 09:58:39,109 - world_sim - INFO - World Shape: (94, 51), 536 robots, 504 item zones, 326 stations
Resetting database
2023-06-26 09:58:39,111 - database_world_manager - WARNING - Resetting redis Robots/State
----
2023-06-26 09:58:39,457 - world_sim - INFO - World start: T = 0, DT = 1.0
2023-06-26 09:58:39,458 - world_sim - INFO - Main loop start...
2023-06-26 09:58:39,579 - world_sim - INFO - Step 1 - took 120.622 ms
2023-06-26 09:58:40,563 - world_sim - INFO - Step 2 - took 104.146 ms
2023-06-26 09:58:41,604 - world_sim - INFO - Step 3 - took 142.952 ms
2023-06-26 09:58:42,593 - world_sim - INFO - Step 4 - took 132.396 ms
2023-06-26 09:58:43,563 - world_sim - INFO - Step 5 - took 100.787 ms
2023-06-26 09:58:44,583 - world_sim - INFO - Step 6 - took 120.667 ms
2023-06-26 09:58:45,563 - world_sim - INFO - Step 7 - took 101.179 ms
2023-06-26 09:58:46,574 - world_sim - INFO - Step 8 - took 109.915 ms
2023-06-26 09:58:47,573 - world_sim - INFO - Step 9 - took 108.936 ms
2023-06-26 09:58:48,584 - world_sim - INFO - Step 10 - took 119.119 ms
Timer unit: 1e-07 s

Total time: 1.15994 s
File: C:\Users\sam\Documents\GitHub\mapf-multiagent-robot-planning\dev\world_sim.py
Function: step at line 211

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
   211                                               @profile2
   212                                               def step(self) -> bool:
   213                                                   # For every robot in environment, pop an action and apply it
   214                                                   # check that final state has no robots colliding with walls or
   215                                                   # each other
   216        10      25591.0   2559.1      0.2          self.logger.debug('Step start')
   217        10        177.0     17.7      0.0          t_start = time.perf_counter()
   218        10        149.0     14.9      0.0          self.last_step_start_time = t_start
   219
   220        10    3435820.0 343582.0     29.6          self.robots = self.wdb.get_robots()
   221
   222        10      99835.0   9983.5      0.9          state_changed = self.step_robots()
   223
   224        10     345911.0  34591.1      3.0          self.world_state = self._check_valid_state()
   225        10         64.0      6.4      0.0          self.t += 1
   226
   227        10         27.0      2.7      0.0          if state_changed:
   228                                                       self.wdb.update_robots(self.robots)
   229
   230        10     115312.0  11531.2      1.0          self.wdb.update_timestamp(self.t)
   231
   232        10         78.0      7.8      0.0          update_duration_ms = (time.perf_counter() - t_start)*1000
   233
   234        10       5506.0    550.6      0.0          self.logger.debug(
   235        30        342.0     11.4      0.0              f'Step end, took {update_duration_ms:.3f} ms: '
   236        30         87.0      2.9      0.0              f'T={self.t} VALID={self.world_state} state change={state_changed}')
   237        10         57.0      5.7      0.0          if update_duration_ms > self.dt_sec*1000:
   238                                                       self.logger.error(
   239                                                           f'update took {update_duration_ms:.2f} > {self.dt_sec*1000} ms')
   240                                                   # Log state of world (t and robot info) to DB
   241        10        289.0     28.9      0.0          time_to_next_step_sec = self.get_time_to_next_step_s()
   242        10    2487374.0 248737.4     21.4          json_data = self.state_dict(time_to_next_step_sec)
   243        10    5082697.0 508269.7     43.8          self.wdb.log_world_state(json_data)
   244                                                   # Return if any robot has moved or not
   245        10         45.0      4.5      0.0          return state_changed

For some reason msgpack is slower

Elucidation commented 1 year ago

Notably, self.wdb.get_robots is slightly faster with msgpack, but building the state_dict (a dict with several packed strings) and the log_world_state (which is an xadd) take much longer. other things are comparable, and this is averaged over 10 runs.

Elucidation commented 1 year ago

117 reduces the size of the data enough that json dumps/loads is fast enough for 1k robots

Elucidation commented 1 year ago

117 fixes the majority time sink