We had a problem with performance on a function that calls lots of other funcitons.
Here is how we found which function was causing the problem.
First, add this line to your poastgres.conf file
- track_functions = pl
Then, run your function.
Finally, analyze the results as show below.
Script started on Thu 21 Jul 2011 04:34:23 PM PDT bash-3.2$ exitscreen[2Ppsql psql (9.0.4) Type "help" for help. postgres=# \qselect * from pg_stat_user_functions; postgres=# \c eas_prod [K You are now connected to database "eas_prod". eas_prod=# \c eas_prod q[Kselect * from pg_stat_user_functions; funcid | schemaname | funcname | calls | total_time | self_time --------+------------+----------------------------------+--------+------------+----------- 763121 | avs | process_address_parcel_link | 190570 | 150040 | 102882 404372 | avs | delete_addresses | 1 | 322 | 322 404371 | avs | init_streets_nearest | 1 | 343549 | 343549 404369 | avs | init_avs_addresses | 1 | 592559 | 592442 404370 | avs | init_parcel_points | 1 | 22349 | 22349 404183 | public | _sfmad_address_base_history | 152567 | 16930941 | 16930941 404185 | public | _sfmad_addresses_history | 178206 | 26794 | 26794 404187 | public | _sfmad_address_x_parcels_history | 195119 | 47157 | 47157 404299 | public | _eas_is_date | 9177 | 116 | 116 404305 | public | _eas_insert_base_address | 152567 | 17038590 | 84753 404306 | public | _eas_insert_unit_address | 25639 | 9126 | 5227 404308 | public | _eas_find_equiv_unit_address | 26801 | 2072 | 2072 404373 | avs | find_address_base | 191515 | 81506 | 81506 404374 | avs | find_nearest_street | 306329 | 53249 | 53249 404375 | avs | find_nearest_street_fancy | 153396 | 120053 | 66804 404376 | avs | process_address_base | 191515 | 17762263 | 522113 404377 | avs | process_address_unit | 190686 | 25695 | 14496 404379 | avs | cascade_retire | 1 | 220 | 220 404380 | avs | load | 20 | 18007181 | 68961 (19 rows) eas_prod=# select * from pg_stat_user_functions; eas_prod=# [Kselect func[K[K[K[Ksceh[K[Khemaname, funcname, ( calls[K[K[K[K[Ktotal_time/calls) as avg_tot_time, (self_time/calls as avg>[K_self_time)[K[K[K[K[K[K[K[K[K[K[K[K[K[K[K[K[K[K) as avg_self_time;[K from pg_stat_user_functions; schemaname | funcname | avg_tot_time | avg_self_time ------------+----------------------------------+--------------+--------------- avs | process_address_parcel_link | 0 | 0 avs | delete_addresses | 322 | 322 avs | init_streets_nearest | 343549 | 343549 avs | init_avs_addresses | 592559 | 592442 avs | init_parcel_points | 22349 | 22349 public | _sfmad_address_base_history | 110 | 110 public | _sfmad_addresses_history | 0 | 0 public | _sfmad_address_x_parcels_history | 0 | 0 public | _eas_is_date | 0 | 0 public | _eas_insert_base_address | 111 | 0 public | _eas_insert_unit_address | 0 | 0 public | _eas_find_equiv_unit_address | 0 | 0 avs | find_address_base | 0 | 0 avs | find_nearest_street | 0 | 0 avs | find_nearest_street_fancy | 0 | 0 avs | process_address_base | 92 | 2 avs | process_address_unit | 0 | 0 avs | cascade_retire | 220 | 220 avs | load | 900359 | 3448 (19 rows) eas_prod=# select schemaname, funcname, ( total_time/calls) as avg_tot_time, (self_time/calls) as avg_self_time from pg_stat_user_functions; eas_prod=# select schemaname, funcname, ( total_time/calls) as avg_tot_time, (self_time/calls[1@:[1@:[1@n[1@u[1@m[1@e[1@r[1@i[1@c[1@:[1@:[1@n[1@u[1@m[1@er) as avg_tot_time, (self_time/calls::numeric) as avg_self_time from pg_stat_user_functions; M eas_prod=# select schemaname, funcname, ( total_time/calls::numeri) as avg_tot_time, (self_time/calls::numeric) as avg_self_time from pg_stat_user_functions; ;M eas_prod=# select schemaname, funcname, ( total_time/calls::numeric) as avg_tot_time, (self_time/calls::numeric) as avg_self_time from pg_stat_user_functions;M eas_prod=# select schemaname, funcname, ( total_time/calls::numeric schemaname | funcname | avg_tot_time | avg_self_time ------------+----------------------------------+------------------------+------------------------ avs | process_address_parcel_link | 0.78732224379493099648 | 0.53986461667628692869 avs | delete_addresses | 322.0000000000000000 | 322.0000000000000000 avs | init_streets_nearest | 343549.000000000000 | 343549.000000000000 avs | init_avs_addresses | 592559.000000000000 | 592442.000000000000 avs | init_parcel_points | 22349.000000000000 | 22349.000000000000 public | _sfmad_address_base_history | 110.9738082285159963 | 110.9738082285159963 public | _sfmad_addresses_history | 0.15035408459872282639 | 0.15035408459872282639 public | _sfmad_address_x_parcels_history | 0.24168328045961695171 | 0.24168328045961695171 public | _eas_is_date | 0.01264029639315680506 | 0.01264029639315680506 public | _eas_insert_base_address | 111.6793933157235837 | 0.55551331546140384225 public | _eas_insert_unit_address | 0.35594211942743476735 | 0.20386910565934708842 public | _eas_find_equiv_unit_address | 0.07731054811387634790 | 0.07731054811387634790 avs | find_address_base | 0.42558546327963867060 | 0.42558546327963867060 avs | find_nearest_street | 0.17382944481260344270 | 0.17382944481260344270 avs | find_nearest_street_fancy | 0.78263448851339017967 | 0.43550027380114214191 avs | process_address_base | 92.7460668877111453 | 2.7262250998616296 avs | process_address_unit | 0.13475032251974450143 | 0.07602026367955696800 avs | cascade_retire | 220.0000000000000000 | 220.0000000000000000 avs | load | 900359.050000000000 | 3448.0500000000000000 (19 rows) eas_prod=# select schemaname, funcname, ( total_time/calls::numeric) as avg_tot_time, (self_time/calls::numeric) as avg_self_time from pg_stat_user_functions s; M eas_prod=# select schemaname, funcname, ( total_time/calls::numeric) as avg_tot_time, (self_time/calls::numeric) as avg_self_time from pg_stat_user_functio (self_time/calls::numeric) as avg_self_time from pg_stat_user_functions;[KM eas_prod=# select schemaname, funcname, ( total_time/calls::numeric) as avg_tot_time (self_time/calls::numeric) as avg_self_time from pg_stat_user_functions; [KM eas_prod=# select schemaname, funcname, ( total_time/calls::numeric) as avg_tot_tim[1P [KM eas_prod=# select schemaname, funcname, ( total_time/calls::numeric) as avg_tot_ti[1P[1P[1P[1P[1P[1P[1P[1P[1P[1P[1P[1P[1P[1P[1P[1P[1P[1P[1P[1P[1P[1P[1P[1P[1P[1P[1P[1P[1P[1@1[1@0[1@0[1@0[1@:[1@:[1@n[1@u[1@m[1@e[1@r[1@i[1@c[1@) eas_prod=# select schemaname, funcname, ( total_time/1000::numeric) [1@ [1@a[1@s eas_prod=# select schemaname, funcname, ( total_time/1000::numeric) as [1@ [1@t[1@o[1@t[1@a[1@l[1@_[1@s[1@, schemaname | funcname | total_s | avg_self_time ------------+----------------------------------+------------------------+------------------------ avs | process_address_parcel_link | 150.0400000000000000 | 0.53986461667628692869 avs | delete_addresses | 0.32200000000000000000 | 322.0000000000000000 avs | init_streets_nearest | 343.5490000000000000 | 343549.000000000000 avs | init_avs_addresses | 592.5590000000000000 | 592442.000000000000 avs | init_parcel_points | 22.3490000000000000 | 22349.000000000000 public | _sfmad_address_base_history | 16930.941000000000 | 110.9738082285159963 public | _sfmad_addresses_history | 26.7940000000000000 | 0.15035408459872282639 public | _sfmad_address_x_parcels_history | 47.1570000000000000 | 0.24168328045961695171 public | _eas_is_date | 0.11600000000000000000 | 0.01264029639315680506 public | _eas_insert_base_address | 17038.590000000000 | 0.55551331546140384225 public | _eas_insert_unit_address | 9.1260000000000000 | 0.20386910565934708842 public | _eas_find_equiv_unit_address | 2.0720000000000000 | 0.07731054811387634790 avs | find_address_base | 81.5060000000000000 | 0.42558546327963867060 avs | find_nearest_street | 53.2490000000000000 | 0.17382944481260344270 avs | find_nearest_street_fancy | 120.0530000000000000 | 0.43550027380114214191 avs | process_address_base | 17762.263000000000 | 2.7262250998616296 avs | process_address_unit | 25.6950000000000000 | 0.07602026367955696800 avs | cascade_retire | 0.22000000000000000000 | 220.0000000000000000 avs | load | 18007.181000000000 | 3448.0500000000000000 (19 rows) eas_prod=# select schemaname, funcname, ( total_time/1000::numeric) as total_s, (self_time/calls::numeric) as avg_self_time from pg_stat_user_functions;[1P[1@6 eas_prod=# select schemaname, funcname, ( total_time/6000[1@0 eas_prod=# select schemaname, funcname, ( total_time/600 eas_prod=# select schemaname, funcname, ( total_time/6000 eas_prod=# select schemaname, funcname, ( total_time/60000 eas_prod=# select schemaname, funcname, ( total_time/60000: eas_prod=# select schemaname, funcname, ( total_time/60000:: eas_prod=# select schemaname, funcname, ( total_time/60000::n eas_prod=# select schemaname, funcname, ( total_time/60000::nu eas_prod=# select schemaname, funcname, ( total_time/60000::num eas_prod=# select schemaname, funcname, ( total_time/60000::nume eas_prod=# select schemaname, funcname, ( total_time/60000::numer eas_prod=# select schemaname, funcname, ( total_time/60000::numeri eas_prod=# select schemaname, funcname, ( total_time/60000::numeric eas_prod=# select schemaname, funcname, ( total_time/60000::numeric) eas_prod=# select schemaname, funcname, ( total_time/60000::numeric) eas_prod=# select schemaname, funcname, ( total_time/60000::numeric) a eas_prod=# select schemaname, funcname, ( total_time/60000::numeric) as eas_prod=# select schemaname, funcname, ( total_time/60000::numeric) as eas_prod=# select schemaname, funcname, ( total_time/60000::numeric) as t eas_prod=# select schemaname, funcname, ( total_time/60000::numeric) as to eas_prod=# select schemaname, funcname, ( total_time/60000::numeric) as tot eas_prod=# select schemaname, funcname, ( total_time/60000::numeric) as tota eas_prod=# select schemaname, funcname, ( total_time/60000::numeric) as total eas_prod=# select schemaname, funcname, ( total_time/60000::numeric) as total_ eas_prod=# select schemaname, funcname, ( total_time/60000::numeric) as total_s[1P[1@m schemaname | funcname | total_m | avg_self_time ------------+----------------------------------+------------------------+------------------------ avs | process_address_parcel_link | 2.5006666666666667 | 0.53986461667628692869 avs | delete_addresses | 0.00536666666666666667 | 322.0000000000000000 avs | init_streets_nearest | 5.7258166666666667 | 343549.000000000000 avs | init_avs_addresses | 9.8759833333333333 | 592442.000000000000 avs | init_parcel_points | 0.37248333333333333333 | 22349.000000000000 public | _sfmad_address_base_history | 282.1823500000000000 | 110.9738082285159963 public | _sfmad_addresses_history | 0.44656666666666666667 | 0.15035408459872282639 public | _sfmad_address_x_parcels_history | 0.78595000000000000000 | 0.24168328045961695171 public | _eas_is_date | 0.00193333333333333333 | 0.01264029639315680506 public | _eas_insert_base_address | 283.9765000000000000 | 0.55551331546140384225 public | _eas_insert_unit_address | 0.15210000000000000000 | 0.20386910565934708842 public | _eas_find_equiv_unit_address | 0.03453333333333333333 | 0.07731054811387634790 avs | find_address_base | 1.3584333333333333 | 0.42558546327963867060 avs | find_nearest_street | 0.88748333333333333333 | 0.17382944481260344270 avs | find_nearest_street_fancy | 2.0008833333333333 | 0.43550027380114214191 avs | process_address_base | 296.0377166666666667 | 2.7262250998616296 avs | process_address_unit | 0.42825000000000000000 | 0.07602026367955696800 avs | cascade_retire | 0.00366666666666666667 | 220.0000000000000000 avs | load | 300.1196833333333333 | 3448.0500000000000000 (19 rows) eas_prod=# select schemaname, funcname, ( total_time/60000::numeric) as total_m, (self_time/calls::numeric) as avg_self_time from pg_stat_user_functions; eas_prod=# select schemaname, funcname, ( total[1P[1P[1P[1P[1P[1@s[1@e[1@l[1@f schemaname | funcname | total_m | avg_self_time ------------+----------------------------------+------------------------+------------------------ avs | process_address_parcel_link | 1.7147000000000000 | 0.53986461667628692869 avs | delete_addresses | 0.00536666666666666667 | 322.0000000000000000 avs | init_streets_nearest | 5.7258166666666667 | 343549.000000000000 avs | init_avs_addresses | 9.8740333333333333 | 592442.000000000000 avs | init_parcel_points | 0.37248333333333333333 | 22349.000000000000 public | _sfmad_address_base_history | 282.1823500000000000 | 110.9738082285159963 public | _sfmad_addresses_history | 0.44656666666666666667 | 0.15035408459872282639 public | _sfmad_address_x_parcels_history | 0.78595000000000000000 | 0.24168328045961695171 public | _eas_is_date | 0.00193333333333333333 | 0.01264029639315680506 public | _eas_insert_base_address | 1.4125500000000000 | 0.55551331546140384225 public | _eas_insert_unit_address | 0.08711666666666666667 | 0.20386910565934708842 public | _eas_find_equiv_unit_address | 0.03453333333333333333 | 0.07731054811387634790 avs | find_address_base | 1.3584333333333333 | 0.42558546327963867060 avs | find_nearest_street | 0.88748333333333333333 | 0.17382944481260344270 avs | find_nearest_street_fancy | 1.11340000000000000000 | 0.43550027380114214191 avs | process_address_base | 8.7018833333333333 | 2.7262250998616296 avs | process_address_unit | 0.24160000000000000000 | 0.07602026367955696800 avs | cascade_retire | 0.00366666666666666667 | 220.0000000000000000 avs | load | 1.14935000000000000000 | 3448.0500000000000000 (19 rows) eas_prod=# select null is not distinct from numm[K[Kll; ?column? ---------- t (1 row) eas_prod=# select null is not distinct from null;[1P[1P[1P[1P[1@1 ?column? ---------- f (1 row) eas_prod=# \q bash-3.2$ exit exit Script done on Thu 21 Jul 2011 05:01:33 PM PDT
Add Comment