Timing information in logs is incorrect

[jeffbl]

It looks like the timings are being ended for each preprocessor just as each one is run, rather than after it returns results. This means all the times are super short, and not useful for determining things like how long LMM remote calls are taking to execute. Log from recent query on unicorn below. Note that all the [Timing] tagged lines are immediately after the orchestrator sends the request, and the timestamps of the actual work being done by those same preprocessors comes only after the Timing information has already been output:

rchestrator-1                    | 2024-12-07T23:11:07.740406431Z Running preprocessors in parallel...                                                                                                                                                       
orchestrator-1                    | 2024-12-07T23:11:07.740433091Z Now on priority group 1                                                                                                                                                                    
orchestrator-1                    | 2024-12-07T23:11:07.745274019Z Sending to preprocessor "content-categoriser"                                                                                                                                              
orchestrator-1                    | 2024-12-07T23:11:07.749962151Z Sending to preprocessor "graphic-caption"                                                                                                                                                  
orchestrator-1                    | 2024-12-07T23:11:07.753502938Z Sending to preprocessor "collage-detector-preprocessor"                                                                                                                                    
orchestrator-1                    | 2024-12-07T23:11:07.757077038Z Sending to preprocessor "line-charts"                                                                                                                                                      
orchestrator-1                    | 2024-12-07T23:11:07.760584553Z Sending to preprocessor "autour-preprocessor"                                                                                                                                              
orchestrator-1                    | 2024-12-07T23:11:07.765583227Z [Timing] Preprocessor "content-categoriser": Execution Time: 20.177 ms, CPU Time: 20.176 ms, Normalized CPU Usage: 6.25%                                                                   
orchestrator-1                    | 2024-12-07T23:11:07.765600881Z [Timing] Preprocessor "graphic-caption": Execution Time: 15.613 ms, CPU Time: 16.213 ms, Normalized CPU Usage: 6.49%                                                                       
orchestrator-1                    | 2024-12-07T23:11:07.765606782Z [Timing] Preprocessor "collage-detector-preprocessor": Execution Time: 12.079 ms, CPU Time: 12.823 ms, Normalized CPU Usage: 6.635%                                                        
orchestrator-1                    | 2024-12-07T23:11:07.765623954Z [Timing] Preprocessor "line-charts": Execution Time: 8.532 ms, CPU Time: 9.053 ms, Normalized CPU Usage: 6.632%                                                                            
orchestrator-1                    | 2024-12-07T23:11:07.765657888Z [Timing] Preprocessor "autour-preprocessor": Execution Time: 5.048 ms, CPU Time: 5.359 ms, Normalized CPU Usage: 6.635%                                                                    
content-categoriser-1             | 2024-12-07T23:11:07.767434874Z [2024-12-07 23:11:07 +0000] [7] [DEBUG] POST /preprocessor                                                                                                                                 
content-categoriser-1             | 2024-12-07T23:11:07.767831088Z DEBUG:root:Received request                                                                                                                                                                
collage-detector-preprocessor-1   | 2024-12-07T23:11:07.768269551Z [2024-12-07 23:11:07 +0000] [7] [DEBUG] POST /preprocessor                                                                                                                                 
line-charts-1                     | 2024-12-07T23:11:07.768272616Z [2024-12-07 23:11:07 +0000] [7] [DEBUG] POST /preprocessor                                                                                                                                 
autour-preprocessor-1             | 2024-12-07T23:11:07.768732380Z [2024-12-07 23:11:07 +0000] [7] [DEBUG] POST /preprocessor                                                                                                                                 
collage-detector-preprocessor-1   | 2024-12-07T23:11:07.769115319Z DEBUG:root:Received request                                                                                                                                                                
autour-preprocessor-1             | 2024-12-07T23:11:07.769549624Z DEBUG:root:Received request                                                                                                                                                                
line-charts-1                     | 2024-12-07T23:11:07.769764618Z DEBUG:root:Received request                                                                                                                                                                
graphic-caption-1                 | 2024-12-07T23:11:07.775121194Z [2024-12-07 23:11:07 +0000] [7] [DEBUG] POST /preprocessor                                                                                                                                 
graphic-caption-1                 | 2024-12-07T23:11:07.775386532Z DEBUG:root:Received request                                                                                                                                                                
content-categoriser-1             | 2024-12-07T23:11:07.778872506Z DEBUG:root:OLLAMA_URL https://ollama.pegasus.cim.mcgill.ca/ollama/api/generate                                                                                                             
content-categoriser-1             | 2024-12-07T23:11:07.778904436Z DEBUG:root:OLLAMA_API_KEY looks properly formatted: sk-[redacted]                                                                                                                          
content-categoriser-1             | 2024-12-07T23:11:07.778960462Z DEBUG:root:serializing json from request_data dictionary                                                                                                                                   
content-categoriser-1             | 2024-12-07T23:11:07.780270140Z DEBUG:root:serialization complete                                                                                                                                                          
content-categoriser-1             | 2024-12-07T23:11:07.780296289Z DEBUG:root:Posting request to ollama model llama3.2-vision:latest                                                                                                                          
content-categoriser-1             | 2024-12-07T23:11:07.781486654Z DEBUG:urllib3.connectionpool:Starting new HTTPS connection (1): ollama.pegasus.cim.mcgill.ca:443                                                                                           
graphic-caption-1                 | 2024-12-07T23:11:07.782034202Z DEBUG:root:OLLAMA_URL https://ollama.pegasus.cim.mcgill.ca/ollama/api/generate                                                                                                             
graphic-caption-1                 | 2024-12-07T23:11:07.782057165Z DEBUG:root:OLLAMA_API_KEY looks properly formatted: sk-[redacted]                                                                                                                          
graphic-caption-1                 | 2024-12-07T23:11:07.782065471Z DEBUG:root:serializing json from request_data dictionary                                                                                                                                   
graphic-caption-1                 | 2024-12-07T23:11:07.782835547Z DEBUG:root:Posting request to ollama model llama3.2-vision:latest