Re: there is a great difference between the query execution time andthe log record time

On 02/08/2018 08:35 AM, dbyzaa@163.com wrote:
> Hi,everybody recently, I found some slow SQL runtime as long as 4 
> seconds in postgres log. However, when I was executing on PSQL client, 
> it takes only 3.6 milliseconds, I did the following things.
> 
> 1. add auto_explain
> session_preload_libraries = 'auto_explain'
> auto_explain.log_min_duration = 100
> auto_explain.log_analyze = true
> auto_explain.log_buffers = true
> ​
> 2. set lock debug
> log_lock_waits = on
> deadlock_timeout = 500ms
> log_min_duration_statement = 100
> 
> 
>     Then i find it takes only 2 milliseconds(auto_explain),but in
>     postgres log it takes 4 seconds, please help me find this problem!!!

What client is running the SQL that shows up in the log?

> 
> 
>     env information
> 
> $ uname -a
> Linux 3.10.0-693.el7.x86_64 #1 SMP Wed Aug 2 06:49:08 PDT 2017 x86_64 
> x86_64 x86_64 GNU/Linux
> ​
> postgres=> select version();
>                                              version
> ---------------------------------------------------------------------------------------------------
> PostgreSQL 9.6.2, compiled by gcc (GCC) 4.4.7 20120313 (Red Hat 
> 4.4.7-18), 64-bit
> ​
> 
> 
>     slow sql log
> 
> 
> 2018-02-06 14:52:52.097 
> CST,"postgres","database",63747,"KFCS2-14:58241",5a794e91.f903,3,"SELECT",2018-02-06 
> 14:43:29 CST,5/1111554,0,LOG,00000,"duration: 4347.635 ms execute 
> <unnamed>: select orderprodu0_.order_id as order_id1_19_, 
> orderprodu0_.amount1 as amount2_19_, orderprodu0_.amount2 as 
> amount3_19_, orderprodu0_.amount3 as amount4_19_, orderprodu0_.amount4 
> as amount5_19_, orderprodu0_.amount5 as amount6_19_, 
> orderprodu0_.auto_confirm_time as auto_con7_19_, 
> orderprodu0_.bestowed_sum_score as bestowed8_19_, 
> orderprodu0_.board_train_code as board_tr9_19_, orderprodu0_.bureau_code 
> as bureau_10_19_, orderprodu0_.coach_no as coach_n11_19_, 
> orderprodu0_.comments_info1 as comment12_19_, 
> orderprodu0_.comments_info2 as comment13_19_, 
> orderprodu0_.company_abbreviation as company14_19_, 
> orderprodu0_.company_id as company15_19_, orderprodu0_.complain_flag as 
> complai16_19_, orderprodu0_.day_night as day_nig17_19_, 
> orderprodu0_.deliver_mode as deliver18_19_, 
> orderprodu0_.destination_code as destina19_19_, 
> orderprodu0_.destination_name as destina20_19_, 
> orderprodu0_.destination_type as destina21_19_, orderprodu0_.drawee_name 
> as drawee_22_19_, orderprodu0_.evaluate_flag as evaluat23_19_, 
> orderprodu0_.exception_flag as excepti24_19_, orderprodu0_.flag1 as 
> flag25_19_, orderprodu0_.flag2 as flag26_19_, orderprodu0_.flag3 as 
> flag27_19_, orderprodu0_.flag4 as flag28_19_, orderprodu0_.flag5 as 
> flag29_19_, orderprodu0_.freight as freight30_19_, 
> orderprodu0_.from_station_name as from_st31_19_, 
> orderprodu0_.from_tele_code as from_te32_19_, orderprodu0_.group_no as 
> group_n33_19_, orderprodu0_.invoice_email as invoice34_19_, 
> orderprodu0_.invoice_flag as invoice35_19_, orderprodu0_.invoice_state 
> as invoice36_19_, orderprodu0_.last_modify_time as last_mo37_19_, 
> orderprodu0_.made_flag as made_fl38_19_, orderprodu0_.mobile as 
> mobile39_19_, orderprodu0_.natural_day as natural40_19_, 
> orderprodu0_.office_no as office_41_19_, orderprodu0_.operator_id as 
> operato42_19_, orderprodu0_.order_batch as order_b43_19_, 
> orderprodu0_.order_code as order_c44_19_, orderprodu0_.order_date as 
> order_d45_19_, orderprodu0_.order_day as order_d46_19_, 
> orderprodu0_.order_pay_method as order_p47_19_, 
> orderprodu0_.order_pay_type as order_p48_19_, orderprodu0_.order_state 
> as order_s49_19_, orderprodu0_.order_total_price as order_t50_19_, 
> orderprodu0_.orders_out_time as orders_51_19_, 
> orderprodu0_.passenger_name as passeng52_19_, 
> orderprodu0_.passenger_phone as passeng53_19_, orderprodu0_.pay_out_time 
> as pay_out54_19_, orderprodu0_.payment_info_id as payment55_19_, 
> orderprodu0_.print_time as print_t56_19_, 
> orderprodu0_.product_total_price as product57_19_, 
> orderprodu0_.return_reason as return_58_19_, orderprodu0_.sales_channels 
> as sales_c59_19_, orderprodu0_.seat_no as seat_no60_19_, 
> orderprodu0_.seat_type_code as seat_ty61_19_, orderprodu0_.sell_station 
> as sell_st62_19_, orderprodu0_.sequence_no as sequenc63_19_, 
> orderprodu0_.service_date as service64_19_, orderprodu0_.service_time as 
> service65_19_, orderprodu0_.start_time as start_t66_19_, 
> orderprodu0_.start_train_date as start_t67_19_, 
> orderprodu0_.start_train_time as start_t68_19_, 
> orderprodu0_.statistics_date as statist69_19_, 
> orderprodu0_.synchronous_flag as synchro70_19_, 
> orderprodu0_.synchronous_time as synchro71_19_, orderprodu0_.ticket_no 
> as ticket_72_19_, orderprodu0_.to_station_name as to_stat73_19_, 
> orderprodu0_.to_tele_code as to_tele74_19_, orderprodu0_.train_code as 
> train_c75_19_, orderprodu0_.train_date as train_d76_19_, 
> orderprodu0_.train_no as train_n77_19_, orderprodu0_.train_setname as 
> train_s78_19_, orderprodu0_.transmit_flag as transmi79_19_, 
> orderprodu0_.transmit_time as transmi80_19_, orderprodu0_.user_id as 
> user_id81_19_, orderprodu0_.user_name as user_na82_19_, 
> orderprodu0_.valid_flag as valid_f83_19_, orderprodu0_.window_no as 
> window_84_19_ from tablename orderprodu0_ where 
> orderprodu0_.company_id=$1 and orderprodu0_.destination_code=$2 and 
> (orderprodu0_.order_state not in ('0' , '1' , '2' , '3')) and 
> orderprodu0_.service_date>=$3 and orderprodu0_.service_date<=$4 order by 
> orderprodu0_.service_date asc","parameters: $1 = '86716', $2 = 'ZAF', $3 
> = '20180201', $4 = '20180228'",,,,,,,,""
> 
> 
>     auto_expain log
> 
> 2018-02-06 14:52:53.731 
> CST,"postgres","dataname",63747,"KFCS2-14:58241",5a794e91.f903,4,"BIND",2018-02-06 
> 14:43:29 CST,5/1111554,0,LOG,00000,"duration: 4347.624 ms plan:
> Query Text: select orderprodu0_.order_id as order_id1_19_, 
> orderprodu0_.amount1 as amount2_19_, orderprodu0_.amount2 as 
> amount3_19_, orderprodu0_.amount3 as amount4_19_, orderprodu0_.amount4 
> as amount5_19_, orderprodu0_.amount5 as amount6_19_, 
> orderprodu0_.auto_confirm_time as auto_con7_19_, 
> orderprodu0_.bestowed_sum_score as bestowed8_19_, 
> orderprodu0_.board_train_code as board_tr9_19_, orderprodu0_.bureau_code 
> as bureau_10_19_, orderprodu0_.coach_no as coach_n11_19_, 
> orderprodu0_.comments_info1 as comment12_19_, 
> orderprodu0_.comments_info2 as comment13_19_, 
> orderprodu0_.company_abbreviation as company14_19_, 
> orderprodu0_.company_id as company15_19_, orderprodu0_.complain_flag as 
> complai16_19_, orderprodu0_.day_night as day_nig17_19_, 
> orderprodu0_.deliver_mode as deliver18_19_, 
> orderprodu0_.destination_code as destina19_19_, 
> orderprodu0_.destination_name as destina20_19_, 
> orderprodu0_.destination_type as destina21_19_, orderprodu0_.drawee_name 
> as drawee_22_19_, orderprodu0_.evaluate_flag as evaluat23_19_, 
> orderprodu0_.exception_flag as excepti24_19_, orderprodu0_.flag1 as 
> flag25_19_, orderprodu0_.flag2 as flag26_19_, orderprodu0_.flag3 as 
> flag27_19_, orderprodu0_.flag4 as flag28_19_, orderprodu0_.flag5 as 
> flag29_19_, orderprodu0_.freight as freight30_19_, 
> orderprodu0_.from_station_name as from_st31_19_, 
> orderprodu0_.from_tele_code as from_te32_19_, orderprodu0_.group_no as 
> group_n33_19_, orderprodu0_.invoice_email as invoice34_19_, 
> orderprodu0_.invoice_flag as invoice35_19_, orderprodu0_.invoice_state 
> as invoice36_19_, orderprodu0_.last_modify_time as last_mo37_19_, 
> orderprodu0_.made_flag as made_fl38_19_, orderprodu0_.mobile as 
> mobile39_19_, orderprodu0_.natural_day as natural40_19_, 
> orderprodu0_.office_no as office_41_19_, orderprodu0_.operator_id as 
> operato42_19_, orderprodu0_.order_batch as order_b43_19_, 
> orderprodu0_.order_code as order_c44_19_, orderprodu0_.order_date as 
> order_d45_19_, orderprodu0_.order_day as order_d46_19_, 
> orderprodu0_.order_pay_method as order_p47_19_, 
> orderprodu0_.order_pay_type as order_p48_19_, orderprodu0_.order_state 
> as order_s49_19_, orderprodu0_.order_total_price as order_t50_19_,
> orderprodu0_.orders_out_time as orders_51_19_, 
> orderprodu0_.passenger_name as passeng52_19_, 
> orderprodu0_.passenger_phone as passeng53_19_, orderprodu0_.pay_out_time 
> as pay_out54_19_, orderprodu0_.payment_info_id as payment55_19_, 
> orderprodu0_.print_time as print_t56_19_, 
> orderprodu0_.product_total_price as product57_19_, 
> orderprodu0_.return_reason as return_58_19_, orderprodu0_.sales_channels 
> as sales_c59_19_, orderprodu0_.seat_no as seat_no60_19_, 
> orderprodu0_.seat_type_code as seat_ty61_19_, orderprodu0_.sell_station 
> as sell_st62_19_, orderprodu0_.sequence_no as sequenc63_19_, 
> orderprodu0_.service_date as service64_19_, orderprodu0_.service_time as 
> service65_19_, orderprodu0_.start_time as start_t66_19_, 
> orderprodu0_.start_train_date as start_t67_19_, 
> orderprodu0_.start_train_time as start_t68_19_, 
> orderprodu0_.statistics_date as statist69_19_, 
> orderprodu0_.synchronous_flag as synchro70_19_, 
> orderprodu0_.synchronous_time as synchro71_19_, orderprodu0_.ticket_no 
> as ticket_72_19_, orderprodu0_.to_station_name as to_stat73_19_, 
> orderprodu0_.to_tele_code as to_tele74_19_, orderprodu0_.train_code as 
> train_c75_19_, orderprodu0_.train_date as train_d76_19_, 
> orderprodu0_.train_no as train_n77_19_, orderprodu0_.train_setname as 
> train_s78_19_, orderprodu0_.transmit_flag as transmi79_19_, 
> orderprodu0_.transmit_time as transmi80_19_, orderprodu0_.user_id as 
> user_id81_19_, orderprodu0_.user_name as user_na82_19_, 
> orderprodu0_.valid_flag as valid_f83_19_, orderprodu0_.window_no as 
> window_84_19_ from tablename orderprodu0_ where 
> orderprodu0_.company_id=$1 and orderprodu0_.destination_code=$2 and 
> (orderprodu0_.order_state not in ('0' , '1' , '2' , '3')) and 
> orderprodu0_.service_date>=$3 and orderprodu0_.service_date<=$4 order by 
> orderprodu0_.service_date asc
> Sort (cost=200.02..200.03 rows=4 width=1661) (actual time=1.991..2.076 
> rows=338 loops=1)
> Sort Key: service_date
> Sort Method: quicksort Memory: 220kB
> Buffers: shared hit=345
> -> Bitmap Heap Scan on tablename orderprodu0_ (cost=4.25..199.98 rows=4 
> width=1661) (actual time=0.182..0.944 rows=338 loops=1)
>        Recheck Cond: ((company_id = '86716'::bigint) AND 
> ((service_date)::text >= '20180201'::text) AND ((service_date)::text <= 
> '20180228'::text))
>        Filter: (((destination_code)::text = 'ZAF'::text) AND 
> ((order_state)::text <> ALL ('{0,1,2,3}'::text[])))
>        Rows Removed by Filter: 23
>        Heap Blocks: exact=340
>        Buffers: shared hit=345
>        -> Bitmap Index Scan on tablename_index1 (cost=0.00..4.25 rows=66 
> width=0) (actual time=0.107..0.107 rows=398 loops=1)
>              Index Cond: ((company_id = '86716'::bigint) AND 
> ((service_date)::text >= '20180201'::text) AND ((service_date)::text <= 
> '20180228'::text))
>              Buffers: shared hit=5",,,,,,,,,""
> 
> 
>     run on psql client
> 
> # explain (analyze,buffers,timing,costs) select orderprodu0_.order_id as 
> order_id1_19_, orderprodu0_.amount1 as amount2_19_, orderprodu0_.amount2 
> as amount3_19_, orderprodu0_.amount3 as amount4_19_, 
> orderprodu0_.amount4 as amount5_19_, orderprodu0_.amount5 as 
> amount6_19_, orderprodu0_.auto_confirm_time as auto_con7_19_, 
> orderprodu0_.bestowed_sum_score as bestowed8_19_, 
> orderprodu0_.board_train_code as board_tr9_19_, orderprodu0_.bureau_code 
> as bureau_10_19_, orderprodu0_.coach_no as coach_n11_19_, 
> orderprodu0_.comments_info1 as comment12_19_, 
> orderprodu0_.comments_info2 as comment13_19_, 
> orderprodu0_.company_abbreviation as company14_19_, 
> orderprodu0_.company_id as company15_19_, orderprodu0_.complain_flag as 
> complai16_19_, orderprodu0_.day_night as day_nig17_19_, 
> orderprodu0_.deliver_mode as deliver18_19_, 
> orderprodu0_.destination_code as destina19_19_, 
> orderprodu0_.destination_name as destina20_19_, 
> orderprodu0_.destination_type as destina21_19_, orderprodu0_.drawee_name 
> as drawee_22_19_, orderprodu0_.evaluate_flag as evaluat23_19_, 
> orderprodu0_.exception_flag as excepti24_19_, orderprodu0_.flag1 as 
> flag25_19_, orderprodu0_.flag2 as flag26_19_, orderprodu0_.flag3 as 
> flag27_19_, orderprodu0_.flag4 as flag28_19_, orderprodu0_.flag5 as 
> flag29_19_, orderprodu0_.freight as freight30_19_, 
> orderprodu0_.from_station_name as from_st31_19_, 
> orderprodu0_.from_tele_code as from_te32_19_, orderprodu0_.group_no as 
> group_n33_19_, orderprodu0_.invoice_email as invoice34_19_, 
> orderprodu0_.invoice_flag as invoice35_19_, orderprodu0_.invoice_state 
> as invoice36_19_, orderprodu0_.last_modify_time as last_mo37_19_, 
> orderprodu0_.made_flag as made_fl38_19_, orderprodu0_.mobile as 
> mobile39_19_, orderprodu0_.natural_day as natural40_19_, 
> orderprodu0_.office_no as office_41_19_, orderprodu0_.operator_id as 
> operato42_19_, orderprodu0_.order_batch as order_b43_19_, 
> orderprodu0_.order_code as order_c44_19_, orderprodu0_.order_date as 
> order_d45_19_, orderprodu0_.order_day as order_d46_19_, 
> orderprodu0_.order_pay_method as order_p47_19_, 
> orderprodu0_.order_pay_type as order_p48_19_, orderprodu0_.order_state 
> as order_s49_19_, orderprodu0_.order_total_price as order_t50_19_, 
> orderprodu0_.orders_out_time as orders_51_19_, 
> orderprodu0_.passenger_name as passeng52_19_, 
> orderprodu0_.passenger_phone as passeng53_19_, orderprodu0_.pay_out_time 
> as pay_out54_19_, orderprodu0_.payment_info_id as payment55_19_, 
> orderprodu0_.print_time as print_t56_19_, 
> orderprodu0_.product_total_price as product57_19_, 
> orderprodu0_.return_reason as return_58_19_, orderprodu0_.sales_channels 
> as sales_c59_19_, orderprodu0_.seat_no as seat_no60_19_, 
> orderprodu0_.seat_type_code as seat_ty61_19_, orderprodu0_.sell_station 
> as sell_st62_19_, orderprodu0_.sequence_no as sequenc63_19_, 
> orderprodu0_.service_date as service64_19_, orderprodu0_.service_time as 
> service65_19_, orderprodu0_.start_time as start_t66_19_, 
> orderprodu0_.start_train_date as start_t67_19_, 
> orderprodu0_.start_train_time as start_t68_19_, 
> orderprodu0_.statistics_date as statist69_19_, 
> orderprodu0_.synchronous_flag as synchro70_19_, 
> orderprodu0_.synchronous_time as synchro71_19_, orderprodu0_.ticket_no 
> as ticket_72_19_, orderprodu0_.to_station_name as to_stat73_19_, 
> orderprodu0_.to_tele_code as to_tele74_19_, orderprodu0_.train_code as 
> train_c75_19_, orderprodu0_.train_date as train_d76_19_, 
> orderprodu0_.train_no as train_n77_19_, orderprodu0_.train_setname as 
> train_s78_19_, orderprodu0_.transmit_flag as transmi79_19_, 
> orderprodu0_.transmit_time as transmi80_19_, orderprodu0_.user_id as 
> user_id81_19_, orderprodu0_.user_name as user_na82_19_, 
> orderprodu0_.valid_flag as valid_f83_19_, orderprodu0_.window_no as 
> window_84_19_ from sljy_order_product orderprodu0_ where 
> orderprodu0_.company_id='86716' and orderprodu0_.destination_code='ZAF' 
> and (orderprodu0_.order_state not in ('0' , '1' , '2' , '3')) and 
> orderprodu0_.service_date>='20180201' and 
> orderprodu0_.service_date<='20180228' order by orderprodu0_.service_date 
> asc;
>                                                                        
> QUERY PLAN
>
----------------------------------------------------------------------------------------------------------------------------------------------------------
> Sort (cost=232.43..232.44 rows=5 width=1661) (actual time=3.459..3.511 
> rows=490 loops=1)
>    Sort Key: service_date
>    Sort Method: quicksort Memory: 305kB
>    Buffers: shared hit=506
>    -> Bitmap Heap Scan on tablename orderprodu0_ (cost=4.39..232.37 
> rows=5 width=1661) (actual time=0.243..2.123 rows=490 loops=1)
>          Recheck Cond: ((company_id = '86716'::bigint) AND 
> ((service_date)::text >= '20180201'::text) AND ((service_date)::text <= 
> '20180228'::text))
>          Filter: (((destination_code)::text = 'ZAF'::text) AND 
> ((order_state)::text <> ALL ('{0,1,2,3}'::text[])))
>          Rows Removed by Filter: 34
>          Heap Blocks: exact=500
>          Buffers: shared hit=506
>          -> Bitmap Index Scan on tablename_index1 (cost=0.00..4.39 
> rows=77 width=0) (actual time=0.178..0.178 rows=622 loops=1)
>                Index Cond: ((company_id = '86716'::bigint) AND 
> ((service_date)::text >= '20180201'::text) AND ((service_date)::text <= 
> '20180228'::text))
>                Buffers: shared hit=6
> Planning time: 0.307 ms
> Execution time: 3.588 ms
> (15 rows)
> ​
> Time: 4.489 ms
> 
> 
> ------------------------------------------------------------------------
> dbyzaa@163.com


-- 
Adrian Klaver
adrian.klaver@aklaver.com