AlexTatiyants / pev

Postgres Explain Visualizer
MIT License
2.77k stars 194 forks source link

Actual Duration Loops Need to Divide by Workers + 1 #29

Open jfinzel opened 7 years ago

jfinzel commented 7 years ago

The actual duration is one of the most useful things about Pev, thank you!!! But for 9.6+, the logic of this line needs to be modified: https://github.com/AlexTatiyants/pev/blob/master/app/services/plan-service.ts#L184

// since time is reported for an invidual loop, actual duration must be adjusted by number of loops
        node[this.ACTUAL_DURATION_PROP] = node[this.ACTUAL_DURATION_PROP] * node[this.ACTUAL_LOOPS_PROP];

node[this.ACTUAL_LOOPS_PROP] needs to be divided by the number of workers + 1, apparently. For example plan in a dummy db I have setup:

[{ "Node Type": "Seq Scan",       
 "Parent Relationship": "Outer",
 "Parallel Aware": true,        
 "Relation Name": "loans",      
 "Schema": "public",            
 "Alias": "l",
 "Startup Cost": 0.00,          
 "Total Cost": 97793.50,        
 "Plan Rows": 1,                
 "Plan Width": 29,              
 "Actual Startup Time": 287.685,
 "Actual Total Time": 360.335,  
 "Actual Rows": 0,              
 "Actual Loops": 5,             
 "Output": ["l.loan_id", "l.customer_id", "l.loan_type_id", "l.is_issued", "l.created_at", "l.updated_at"],    
 "Filter": "(l.loan_id = 100)", 
 "Rows Removed by Filter": 2060000,    
 "Shared Hit Blocks": 224,      
 "Shared Read Blocks": 65382,   
 "Shared Dirtied Blocks": 0,    
 "Shared Written Blocks": 0,    
 "Local Hit Blocks": 0,         
 "Local Read Blocks": 0,        
 "Local Dirtied Blocks": 0,     
 "Local Written Blocks": 0,     
 "Temp Read Blocks": 0,         
 "Temp Written Blocks": 0,      
 "Workers": [ 
   {          
     "Worker Number": 0,        
     "Actual Startup Time": 359.434,   
     "Actual Total Time": 359.434,     
     "Actual Rows": 0,          
     "Actual Loops": 1,         
     "Shared Hit Blocks": 46,   
     "Shared Read Blocks": 13050,      
     "Shared Dirtied Blocks": 0,
     "Shared Written Blocks": 0,
     "Local Hit Blocks": 0,     
     "Local Read Blocks": 0,    
     "Local Dirtied Blocks": 0, 
     "Local Written Blocks": 0, 
     "Temp Read Blocks": 0,     
     "Temp Written Blocks": 0   
   },         
   {          
     "Worker Number": 1,        
     "Actual Startup Time": 359.646,   
     "Actual Total Time": 359.646,     
     "Actual Rows": 0,          
     "Actual Loops": 1,         
     "Shared Hit Blocks": 44,   
     "Shared Read Blocks": 13227,      
     "Shared Dirtied Blocks": 0,
     "Shared Written Blocks": 0,
     "Local Hit Blocks": 0,     
     "Local Read Blocks": 0,    
     "Local Dirtied Blocks": 0, 
     "Local Written Blocks": 0, 
     "Temp Read Blocks": 0,     
     "Temp Written Blocks": 0   
   },         
   {          
     "Worker Number": 2,        
     "Actual Startup Time": 359.646,   
     "Actual Total Time": 359.646,     
     "Actual Rows": 0,          
     "Actual Loops": 1,         
     "Shared Hit Blocks": 45,   
     "Shared Read Blocks": 12859,      
     "Shared Dirtied Blocks": 0,
     "Shared Written Blocks": 0,
     "Local Hit Blocks": 0,     
     "Local Read Blocks": 0,    
     "Local Dirtied Blocks": 0, 
     "Local Written Blocks": 0, 
     "Temp Read Blocks": 0,     
     "Temp Written Blocks": 0   
   },         
   {          
     "Worker Number": 3,        
     "Actual Startup Time": 359.658,   
     "Actual Total Time": 359.658,     
     "Actual Rows": 0,          
     "Actual Loops": 1,         
     "Shared Hit Blocks": 42,   
     "Shared Read Blocks": 12875,      
     "Shared Dirtied Blocks": 0,
     "Shared Written Blocks": 0,
     "Local Hit Blocks": 0,     
     "Local Read Blocks": 0,    
     "Local Dirtied Blocks": 0, 
     "Local Written Blocks": 0, 
     "Temp Read Blocks": 0,     
     "Temp Written Blocks": 0   
   }          
 ]
}]

Right now, actual total time of this node is 360.335, but because it shows 5 loops, it is multiplying this by 5.