FEAT: Implement ibis.pandas.trace module to add time and call stack informa…

[icexelloss]

What is the change

This PR add a way to log time and call stack information for pandas backend.

The information can be enabled by turning logging level to DEBUG.

e.g.

import pandas as pd                                                                                                                                                                                                                                                                                                                                                       
import ibis.expr.datatypes as dt                                                                                                                                                                                                                                                                                                                                          
import ibis.pandas                                                                                                                                                                                                                                                                                                                                                        
from ibis.udf.vectorized import elementwise                                                                                                                                                                                                                                                                                                                               
                                                                                                                                                                                                                                                                                                                                                                          
import logging                                                                                                                                                                                                                                                                                                                                                            
                                                                                                                                                                                                                                                                                                                                                                          
logging.basicConfig(level=logging.DEBUG)                                                                                                                                                                                                                                                                                                                                  
                                                                                                                                                                                                                                                                                                                                                                          
df = pd.DataFrame(                                                                                                                                                                                                                                                                                                                                                        
    {                                                                                                                                                                                                                                                                                                                                                                     
        'a': [1, 2, 3]                                                                                                                                                                                                                                                                                                                                                    
    }                                                                                                                                                                                                                                                                                                                                                                     
)                                                                                                                                                                                                                                                                                                                                                                         
                                                                                                                                                                                                                                                                                                                                                                          
con = ibis.pandas.connect({"table1": df})                                                                                                                                                                                                                                                                                                                                 
                                                                                                                                                                                                                                                                                                                                                                          
@elementwise(                                                                                                                                                                                                                                                                                                                                                             
    input_type=[dt.double],                                                                                                                                                                                                                                                                                                                                               
    output_type=dt.double                                                                                                                                                                                                                                                                                                                                                 
)                                                                                                                                                                                                                                                                                                                                                                         
def add_one(v):                                                                                                                                                                                                                                                                                                                                                           
    import time                                                                                                                                                                                                                                                                                                                                                           
    time.sleep(5)                                                                                                                                                                                                                                                                                                                                                         
    return v + 1                                                                                                                                                                                                                                                                                                                                                          
                                                                                                                                                                                                                                                                                                                                                                          
                                                                                                                                                                                                                                                                                                                                                                          
table = con.table("table1")                                                                                                                                                                                                                                                                                                                                               
table = table.mutate(b=add_one(table['a']))                                                                                                                                                                                                                                                                                                                               
table.execute()

Output:

DEBUG:root: main_execute Selection                                                                                                                                                                                                                                                                                                                                        
DEBUG:root:   execute_until_in_scope Selection                                                                                                                                                                                                                                                                                                                            
DEBUG:root:     execute_until_in_scope PandasTable                                                                                                                                                                                                                                                                                                                        
DEBUG:root:       execute_database_table_client PandasTable                                                                                                                                                                                                                                                                                                               
DEBUG:root:       execute_database_table_client PandasTable 0:00:00.000074                                                                                                                                                                                                                                                                                                
DEBUG:root:     execute_until_in_scope PandasTable 0:00:00.000396                                                                                                                                                                                                                                                                                                         
DEBUG:root:     execute_selection_dataframe Selection                                                                                                                                                                                                                                                                                                                     
DEBUG:root:     main_execute ElementWiseVectorizedUDF                                                                                                                                                                                                                                                                                                                     
DEBUG:root:       execute_until_in_scope ElementWiseVectorizedUDF                                                                                                                                                                                                                                                                                                         
DEBUG:root:         execute_until_in_scope TableColumn                                                                                                                                                                                                                                                                                                                    
DEBUG:root:           execute_until_in_scope PandasTable                                                                                                                                                                                                                                                                                                                  
DEBUG:root:           execute_until_in_scope PandasTable 0:00:00.000069                                                                                                                                                                                                                                                                                                   
DEBUG:root:           execute_table_column_df_or_df_groupby TableColumn                                                                                                                                                                                                                                                                                                   
DEBUG:root:           execute_table_column_df_or_df_groupby TableColumn 0:00:00.000324                                                                                                                                                                                                                                                                      
DEBUG:root:         execute_until_in_scope TableColumn 0:00:00.000608                                                                                                                                                                                                                                                                                                     
DEBUG:root:         execute_udf_node ElementWiseVectorizedUDF                                                                                                                                                                                                                                                                                                             
DEBUG:root:         execute_udf_node ElementWiseVectorizedUDF 0:00:05.014354                                                                                                                                                                                                                                                                                              
DEBUG:root:       execute_until_in_scope ElementWiseVectorizedUDF 0:00:05.015450                                                                                                                                                                                                                             
DEBUG:root:     main_execute ElementWiseVectorizedUDF 0:00:05.015659                                                                                                                                                                                                                                                                                                      
DEBUG:root:     execute_selection_dataframe Selection 0:00:05.017459                                                                                                                                                                                                                                                                                                      
DEBUG:root:   execute_until_in_scope Selection 0:00:05.018348                                                                                                                                                                                                                                                                                                             
DEBUG:root: main_execute Selection 0:00:05.020070     

How is the change tested

This is manually tested. If you have some ideas how to test this I am happy to hear.

[jreback]

looks pretty good

i think makes sense to hook this into config: https://github.com/ibis-project/ibis/blob/master/ibis/config_init.py

then i think u can instrument always and just hide it behind the flag
it could still go to logger

[icexelloss]

Thanks @jreback. Make sense, let me hook this into the config.

[emilyreff7]

LGTM

[icexelloss]

@jreback Updated! Can you take another look please?

[jreback]

sp? here

[icexelloss]

Sorry I don't quite get that. What do you by sp?

[jreback]

why do we need this additional complexity here? can you just modify Dispatcher to add (if the config is on)? isn't that the point of using the option.

[icexelloss]

Dispatcher is from multipledispatch library..

[jreback]

lgtm @icexelloss

[jreback]

its going to run the CI again as conflict in the release note, but can merge on green.

[jreback]

thanks @icexelloss
sp? == spelling