Обсуждение: there is a great difference between the query execution time and the log record time

Поиск
Список
Период
Сортировка

there is a great difference between the query execution time and the log record time

От
"dbyzaa@163.com"
Дата:

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!!!

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

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

От
Adrian Klaver
Дата:
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


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

От
Francisco Olarte
Дата:
On Thu, Feb 8, 2018 at 5:35 PM, dbyzaa@163.com <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.
....

You are not doing the same thing ( explain discards all data in the
server ) and your query has a lot of columns. I'm not sure if it does
affect, but are you sure you are not gettin more time for transmitting
the actual result data?

Francisco Olarte.


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

От
nemo
Дата:
Hi,from the explain the sql result is only 338 rows!



--
Sent from: http://www.postgresql-archive.org/PostgreSQL-general-f1843780.html


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

От
nemo
Дата:

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

От
Adrian Klaver
Дата:
On 02/08/2018 08:51 AM, nemo wrote:
> Hi,the client is jdbc.

Is the client on the server or is it remote?

I am not a Java programmer, but for those that are and might be able to 
help could you provide the code that runs the query?

> 
> 
> 
> --
> Sent from: http://www.postgresql-archive.org/PostgreSQL-general-f1843780.html
> 


-- 
Adrian Klaver
adrian.klaver@aklaver.com


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

От
邓彪
Дата:
the client on the remote server!!!


On 02/09/2018 00:54, Adrian Klaver wrote:
On 02/08/2018 08:51 AM, nemo wrote:
> Hi,the client is jdbc.

Is the client on the server or is it remote?

I am not a Java programmer, but for those that are and might be able to
help could you provide the code that runs the query?

>
>
>
> --
> Sent from: http://www.postgresql-archive.org/PostgreSQL-general-f1843780.html
>


--
Adrian Klaver
adrian.klaver@aklaver.com

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

От
Adrian Klaver
Дата:
On 02/08/2018 09:14 AM, 邓彪 wrote:
> the client on the remote server!!!

So when you did the psql test was that local to the server or remote?

Also what is the JDBC remote client doing with the data?
For example is is feeding a GUI form?

> 
> 
>     
> 邓彪
> 邮箱:dbyzaa@163.com
> 
>
<https://maas.mail.163.com/dashi-web-extend/html/proSignature.html?iconUrl=http%3A%2F%2Fmail-online.nosdn.127.net%2F3bcc55931047f433c5f7e66cbb7c36b1.jpg&name=%E9%82%93%E5%BD%AA&uid=example%40163.com&ftlId=3&items=%5B%22%E9%82%AE%E7%AE%B1%EF%BC%9Adbyzaa%40163.com%22%5D>

> 
> 
> 签名由 网易邮箱大师 <https://mail.163.com/dashi/dlpro.html?from=mail88> 定制
> 
> On 02/09/2018 00:54, Adrian Klaver <mailto:adrian.klaver@aklaver.com> 
> wrote:
> 
>     On 02/08/2018 08:51 AM, nemo wrote:
>      > Hi,the client is jdbc.
> 
>     Is the client on the server or is it remote?
> 
>     I am not a Java programmer, but for those that are and might be able to
>     help could you provide the code that runs the query?
> 
>      >
>      >
>      >
>      > --
>      > Sent from:
>     http://www.postgresql-archive.org/PostgreSQL-general-f1843780.html
>      >
> 
> 
>     -- 
>     Adrian Klaver
>     adrian.klaver@aklaver.com
> 


-- 
Adrian Klaver
adrian.klaver@aklaver.com


回复:there is a great difference between the query execution time and the log record time

От
邓彪
Дата:
i test psql on local and remote server are the same!
the jdbc remote client is display data on web page!


邓彪
邮箱:dbyzaa@163.com

签名由 网易邮箱大师 定制

2018年02月09日 01:33Adrian Klaver 写道:
On 02/08/2018 09:14 AM, 邓彪 wrote:
> the client on the remote server!!!

So when you did the psql test was that local to the server or remote?

Also what is the JDBC remote client doing with the data?
For example is is feeding a GUI form?

>
>
>    
> 邓彪
> 邮箱:dbyzaa@163.com
>
> <https://maas.mail.163.com/dashi-web-extend/html/proSignature.html?iconUrl=http%3A%2F%2Fmail-online.nosdn.127.net%2F3bcc55931047f433c5f7e66cbb7c36b1.jpg&name=%E9%82%93%E5%BD%AA&uid=example%40163.com&ftlId=3&items=%5B%22%E9%82%AE%E7%AE%B1%EF%BC%9Adbyzaa%40163.com%22%5D>
>
>
> 签名由 网易邮箱大师 <https://mail.163.com/dashi/dlpro.html?from=mail88> 定制
>
> On 02/09/2018 00:54, Adrian Klaver <mailto:adrian.klaver@aklaver.com>
> wrote:
>
>     On 02/08/2018 08:51 AM, nemo wrote:
>      > Hi,the client is jdbc.
>
>     Is the client on the server or is it remote?
>
>     I am not a Java programmer, but for those that are and might be able to
>     help could you provide the code that runs the query?
>
>      >
>      >
>      >
>      > --
>      > Sent from:
>     http://www.postgresql-archive.org/PostgreSQL-general-f1843780.html
>      >
>
>
>     --
>     Adrian Klaver
>     adrian.klaver@aklaver.com
>


--
Adrian Klaver
adrian.klaver@aklaver.com

Re: 回复:there is a great difference between the query execution time and the log record time

От
Adrian Klaver
Дата:
On 02/08/2018 09:38 AM, 邓彪 wrote:
> i test psql on local and remote server are the same!
> the jdbc remote client is display data on web page!
> 

To me that indicates there is overhead in the Java/JDBC/Web stack that 
causing the statement to take extra time to finish.


-- 
Adrian Klaver
adrian.klaver@aklaver.com