VisionIPCClient: fix slow connect

[sshane]

Can't reproduce on device anymore, but on PC:

Something about this is slow:

https://github.com/commaai/msgq/blob/e0ee68e69d1cb2e208ee13f1632b6e709e615a5a/msgq/visionipc/visionipc_client.cc#L68-L76

As well as this on re-connect:

https://github.com/commaai/msgq/blob/e0ee68e69d1cb2e208ee13f1632b6e709e615a5a/msgq/visionipc/visionipc_client.cc#L37-L42

---

It looks like it's inconsistent because it relies on modeld, dmonitoringmodeld, and/or encoderd connecting to camerad at a certain time. This is the slow line for ui:

https://github.com/commaai/msgq/blob/e0ee68e69d1cb2e208ee13f1632b6e709e615a5a/msgq/visionipc/visionipc_client.cc#L57

Perhaps it wasn't reproducible on mici because startup timing is slightly different, earlier or later, missing the congestion of all the procs connecting.

And this handles incoming connections sequentially:

https://github.com/commaai/msgq/blob/e0ee68e69d1cb2e208ee13f1632b6e709e615a5a/msgq/visionipc/visionipc_server.cc#L86

[github-actions]

mici raylib UI Preview

✅ Videos are identical! View Diff Report

[github-actions]

raylib UI Preview

All Screenshots

[sshane]

I don't totally understand what's going on. Running a few connect loops sleeping 0.1s in the background, then starting cameraview.py, the time taken shifts around. This time it's in importing the buffers:

I also can't reproduce the 300ms+ time taken with the manual fake connect loops unless I start test_onroad.py

comma@comma-7e8e41ad:/data/openpilot$ python selfdrive/ui/onroad/cameraview.py                                                                                                           
Loaded translations for language: en                                                        
gbm_create_device(156): Info: backend name is: msm_drm                                      
[VisionIpcClient::connect] Cleanup old buffers (type=0): 0 us                               
[VisionIpcClient::connect] Connect to VIPC server (type=0): 131 us                          
[VisionIpcClient::connect] Send stream type to server (type=0): 192 us                      
[VisionIpcClient::connect] Get FDs from server (type=0): 53 us                              
[VisionIpcClient::connect] Import buffers (type=0): 58816 us                                
[VisionIpcClient::connect] Finalize (close socket, set connected) (type=0): 43 us           
[VisionIpcClient::connect] Total time (type=0): 59412 us

Then running a few seconds later:

comma@comma-7e8e41ad:/data/openpilot$ python selfdrive/ui/onroad/cameraview.py              
Loaded translations for language: en                                                        
gbm_create_device(156): Info: backend name is: msm_drm                                      
[VisionIpcClient::connect] Cleanup old buffers (type=0): 0 us                               
[VisionIpcClient::connect] Connect to VIPC server (type=0): 12176 us                        
[VisionIpcClient::connect] Send stream type to server (type=0): 1177 us                     
[VisionIpcClient::connect] Get FDs from server (type=0): 48 us                              
[VisionIpcClient::connect] Import buffers (type=0): 18469 us                                
[VisionIpcClient::connect] Finalize (close socket, set connected) (type=0): 41 us           
[VisionIpcClient::connect] Total time (type=0): 32115 us

Then again:

comma@comma-7e8e41ad:/data/openpilot$ python selfdrive/ui/onroad/cameraview.py              
Loaded translations for language: en                                                        
gbm_create_device(156): Info: backend name is: msm_drm                                      
[VisionIpcClient::connect] Cleanup old buffers (type=0): 0 us                               
[VisionIpcClient::connect] Connect to VIPC server (type=0): 171 us                          
[VisionIpcClient::connect] Send stream type to server (type=0): 3280 us                     
[VisionIpcClient::connect] Get FDs from server (type=0): 233 us                             
[VisionIpcClient::connect] Import buffers (type=0): 43879 us                                
[VisionIpcClient::connect] Finalize (close socket, set connected) (type=0): 44 us           
[VisionIpcClient::connect] Total time (type=0): 47808 us 

[sshane]

Hit 500ms, but again only happens with full openpilot stack running naturally:

[VisionIpcClient::connect] Finalize (close socket, set connected) (type=0): 39 us                                                                                    05:19:38 [3271/6995]
[VisionIpcClient::connect] Total time (type=0): 2054 us                                                                                                                                  
[VisionIpcClient::connect] Cleanup old buffers (type=2): 0 us                                                                                                                            
[VisionIpcClient::connect] Connect to VIPC server (type=2): 56 us                                                                                                                        
[VisionIpcServer::listener] Poll took: 1900 us                                                                                                                                           
[VisionIpcClient::connect] Send stream type to server (type=2): 10 us                                                                                                                    
[VisionIpcServer::listener] Accept connection: 20 us                                                                                                                                     
[VisionIpcServer::listener] Receive stream type request (type=2): 6 us                                                                                                                   
[VisionIpcServer::listener] Prepare buffers (type=2, num_fds=18): 6 us                                                                                                                   
[VisionIpcServer::listener] Send buffers + FDs (type=2): 37 us                                                                                                                           
[VisionIpcServer::listener] Close connection (type=2): 24 us                                                                                                                             
[VisionIpcClient::connect] Get FDs from server (type=2): 158 us                                                                                                                          
[VisionIpcClient::connect] Import buffers (type=2): 1544 us                                                                                                                              
[VisionIpcClient::connect] Finalize (close socket, set connected) (type=2): 37 us                                                                                                        
[VisionIpcClient::connect] Total time (type=2): 1887 us                                                                                                                                  
connected main cam with buffer size: 4804608 (1928 x 1208)                                                                                                                               
connected extra cam with buffer size: 4804608 (1928 x 1208)                                                                                                                              
[VisionIpcClient::connect] Get FDs from server (type=0): 513970 us  # <--------------- here's the ui lag                                                                                                                       
[VisionIpcClient::connect] Import buffers (type=0): 770 us                                                                                                                               
[VisionIpcClient::connect] Finalize (close socket, set connected) (type=0): 42 us                                                                                                        
[VisionIpcClient::connect] Total time (type=0): 515079 us                                   
Connected to camerad stream: 0, buffers: 18                                                                                                                                              
[VisionIpcServer::listener] Poll took: 59766 us                                                                                                                                          
[VisionIpcServer::listener] Accept connection: 26 us                                                                                                                                     
[VisionIpcServer::listener] Receive stream type request (type=4): 9 us                                                                                                                   
[VisionIpcServer::listener] Prepare available streams (type=4): 2 us                                                                                                                     
[VisionIpcServer::listener] Send available streams (type=4): 18 us                                                                                                                       
*** CameraView timings ***                                                                                                                                                               
  switch: max 0.00 ms, avg 0.00 ms over 26 calls                                                                                                                                         
  connect: max 517.02 ms, avg 172.34 ms over 3 calls                                                                                                                                     
  recv: max 0.33 ms, avg 0.33 ms over 1 calls                                                                                                                                            
  calc rects: max 1.07 ms, avg 1.07 ms over 1 calls
  render: max 4.54 ms, avg 4.54 ms over 1 calls

[sshane]

I'm starting to doubt that this is the VisionIPC server, after adding a connect thread, now I'm seeing the time move to another part of the ui:

It might be that all of the openpilot procs starting at once is preempting the lower priority ui process. This also explains why I can't reproduce above 50ms with a bunch of clients connecting in a loop

*** AugmentedRoadView timing ***                                                            
  switch_stream: max 0.04 ms, avg 0.01 ms over 78 calls                                     
  update_calib: max 1.60 ms, avg 0.03 ms over 78 calls                                      
  camera render: max 41.91 ms, avg 1.73 ms over 78 calls                                    
  model render: max 0.05 ms, avg 0.03 ms over 78 calls                                      
  UI overlays: max 8.41 ms, avg 0.72 ms over 78 calls                                       
  final overlays: max 731.88 ms, avg 9.74 ms over 78 calls