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
11 stars 3 forks source link

world_sim line profiling #109

Closed Elucidation closed 1 year ago

Elucidation commented 1 year ago

Looking at line_profile for the step function:

mapf-multiagent-robot-planning\dev\world_sim.py
Function: step at line 210

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
   210                                               @profile
   211                                               def step(self) -> bool:
   212                                                   # For every robot in environment, pop an action and apply it
   213                                                   # check that final state has no robots colliding with walls or
   214                                                   # each other
   215        10      18244.0   1824.4      0.3          self.logger.debug('Step start')
   216        10        121.0     12.1      0.0          t_start = time.perf_counter()
   217        10        110.0     11.0      0.0          self.last_step_start_time = t_start
   218
   219        10    3709337.0 370933.7     52.6          self.robots = self.wdb.get_robots()
   220
   221        10     101299.0  10129.9      1.4          state_changed = self.step_robots()
   222
   223        10     354812.0  35481.2      5.0          self.world_state = self._check_valid_state()
   224        10         74.0      7.4      0.0          self.t += 1
   225
   226        10         26.0      2.6      0.0          if state_changed:
   227                                                       self.wdb.update_robots(self.robots)
   228
   229        10     131784.0  13178.4      1.9          self.wdb.update_timestamp(self.t)
   230
   231        10         91.0      9.1      0.0          update_duration_ms = (time.perf_counter() - t_start)*1000
   232
   233        10       5913.0    591.3      0.1          self.logger.debug(
   234        30        385.0     12.8      0.0              f'Step end, took {update_duration_ms:.3f} ms: '
   235        30         89.0      3.0      0.0              f'T={self.t} VALID={self.world_state} state change={state_changed}')
   236        10         68.0      6.8      0.0          if update_duration_ms > self.dt_sec*1000:
   237                                                       self.logger.error(
   238                                                           f'update took {update_duration_ms:.2f} > {self.dt_sec*1000} ms')
   239                                                   # Log state of world (t and robot info) to DB
   240        10        331.0     33.1      0.0          time_to_next_step_sec = self.get_time_to_next_step_s()
   241        10    2731137.0 273113.7     38.7          self.wdb.log_world_state(self.state_dict(time_to_next_step_sec))
   242                                                   # Return if any robot has moved or not
   243        10         32.0      3.2      0.0          return state_changed
Elucidation commented 1 year ago

52.6 and 38.7% (ie. 91.3%) of the total time was take in self.wdb.get_robots() and self.wdb.log_world_state, which are calls to read/write robots from the redis db.

Elucidation commented 1 year ago

Looking a those calls in wdb

PS C:\Users\sam\Documents\GitHub\mapf-multiagent-robot-planning\dev> python -m world_sim
2023-06-26 09:36:43,565 - world_sim - INFO - Connecting to redis server localhost:6379
2023-06-26 09:36:43,721 - world_sim - INFO - World Shape: (94, 51), 536 robots, 504 item zones, 326 stations
2023-06-26 09:36:43,723 - world_sim - INFO - Loading time and dt from DB
2023-06-26 09:36:43,725 - world_sim - INFO - World start: T = 58, DT = 1.0
2023-06-26 09:36:43,726 - world_sim - INFO - Main loop start...
2023-06-26 09:36:43,769 - world_sim - INFO - Step 59 - took 43.499 ms
2023-06-26 09:36:44,827 - world_sim - INFO - Step 60 - took 102.094 ms
2023-06-26 09:36:45,807 - world_sim - INFO - Step 61 - took 81.161 ms
2023-06-26 09:36:46,794 - world_sim - INFO - Step 62 - took 67.211 ms
2023-06-26 09:36:47,774 - world_sim - INFO - Step 63 - took 45.793 ms
2023-06-26 09:36:48,785 - world_sim - INFO - Step 64 - took 57.741 ms
2023-06-26 09:36:49,770 - world_sim - INFO - Step 65 - took 41.870 ms
2023-06-26 09:36:50,816 - world_sim - INFO - Step 66 - took 88.939 ms
2023-06-26 09:36:51,773 - world_sim - INFO - Step 67 - took 44.083 ms
2023-06-26 09:36:52,771 - world_sim - INFO - Step 68 - took 41.740 ms
Timer unit: 1e-07 s

Total time: 0 s
File: C:\Users\sam\Documents\GitHub\mapf-multiagent-robot-planning\dev\world_db.py
Function: update_robots at line 86

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
    86                                               @profile
    87                                               def update_robots(self, robots: List[Robot], pipeline: 'redis.Pipeline' = None):
    88                                                   # Execute update if pipeline not defined, else pass to pipeline.
    89                                                   _pipeline = self.redis.pipeline() if pipeline is None else pipeline
    90                                                   for robot in robots:
    91                                                       robot_key = f'robot:{robot.robot_id}'
    92                                                       _pipeline.hset(robot_key, mapping=robot.json_data())
    93                                                       # Add robot to busy/free based on state
    94                                                       if robot.state == RobotStatus.AVAILABLE:
    95                                                           _pipeline.sadd('robots:free', robot_key)
    96                                                           _pipeline.srem('robots:busy', robot_key)
    97                                                       elif robot.state == RobotStatus.IN_PROGRESS:
    98                                                           _pipeline.sadd('robots:busy', robot_key)
    99                                                           _pipeline.srem('robots:free', robot_key)
   100                                                   if pipeline is None:
   101                                                       _pipeline.execute()

Total time: 0.378628 s
File: C:\Users\sam\Documents\GitHub\mapf-multiagent-robot-planning\dev\world_db.py
Function: get_robots at line 119

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
   119                                               @profile
   120                                               def get_robots(self) -> List[Robot]:
   121        10     204143.0  20414.3      5.4          robot_keys = self.redis.lrange('robots:all', 0, -1)
   122        10       2283.0    228.3      0.1          pipeline = self.redis.pipeline()
   123      5360      26577.0      5.0      0.7          for robot_key in robot_keys:
   124      5360     271399.0     50.6      7.2              pipeline.hgetall(robot_key)
   125        10    1615873.0 161587.3     42.7          robots_json_data = pipeline.execute()
   126        10    1666005.0 166600.5     44.0          return [Robot.from_json(json_data) for json_data in robots_json_data]

Total time: 0.169406 s
File: C:\Users\sam\Documents\GitHub\mapf-multiagent-robot-planning\dev\world_db.py
Function: log_world_state at line 128

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
   128                                               @profile
   129                                               def log_world_state(self, data: dict):
   130                                                   """Add latest world state data to the stream."""
   131        10    1597019.0 159701.9     94.3          self.redis.xadd('world:state', data)
   132        10      97040.0   9704.0      5.7          self.redis.xtrim('world:state', maxlen=100, approximate=True)
Elucidation commented 1 year ago

A portion of the db read/writes includes building the json message 

   241        10    1681552.0 168155.2     20.2          json_data = self.state_dict(time_to_next_step_sec)
   242        10    1222551.0 122255.1     14.7          self.wdb.log_world_state(json_data)
Elucidation commented 1 year ago

Testing with msgpack the timings are unexpectedly worse. #108

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
Elucidation commented 1 year ago

selective updates makes this tractable ~<100ms for 1k robots