Results 1 to 1 of 1
  1. #1
    Join Date
    Sep 2010
    Posts
    1

    Unanswered: Sudden Drop in Performance over Repeated Queries

    Hi, I have a parameterized PostGIS query I am using in an ETL process:

    Code:
    SELECT address_street as building_street, address_city as building_city, address_state as building_state, address_zipcode as building_zipcode, ST_Distance(the_geom, ST_Transform(PointFromText('POINT(' || ? || ' ' || ?  || ')', 4269), 32661))*3.2808399 as distance_to_tower
    FROM dim_address_geo r
    WHERE ST_DWithin(transform(PointFromText('POINT(' || ? || ' ' || ?  || ')', 4269), 32661), r.the_geom, 152.4)
    The question marks are how the ETL software handles parameters.

    I am running a Postgresql DB on my local machine (Ubuntu) as well as it mirrored on a remote server. After trying it on both machines, I am getting the same behavior: after 5 very fast queries, the performance drops dramatically (from only a few milliseconds per query to almost 30 seconds per query). I have tried randomizing the order of the input rows and it does not help. When I run the slow queries directly on the DB, they are very fast, so I don't think the query parameters or the query itself is to blame.

    Here is the output of the logs that show the dramatic increase in query duration. The only thing strange I noticed was that the "parse" step does not show up in the slower queries. Could this be a symptom on the problem? Is it possible that the ETL software is the problem? It is being called through a JDBC driver; could it be corrupted?
    Code:
    2010-09-21 12:00:34.013 EDT,"benkeith","geodjango",24984,"127.0.0.1:33271",4c98d6a0.6198,4,"SELECT",2010-09-21 12:00:32 EDT,1/12,0,LOG,00000,"duration: 2.724 ms",,,,,,,,
    2010-09-21 12:00:34.015 EDT,"benkeith","geodjango",24984,"127.0.0.1:33271",4c98d6a0.6198,5,"PARSE",2010-09-21 12:00:32 EDT,1/13,0,LOG,00000,"duration: 0.254 ms",,,,,,,,
    2010-09-21 12:00:34.016 EDT,"benkeith","geodjango",24984,"127.0.0.1:33271",4c98d6a0.6198,6,"BIND",2010-09-21 12:00:32 EDT,1/13,0,LOG,00000,"duration: 1.014 ms",,,,,,,,
    2010-09-21 12:00:34.017 EDT,"benkeith","geodjango",24984,"127.0.0.1:33271",4c98d6a0.6198,7,"SELECT",2010-09-21 12:00:32 EDT,1/13,0,LOG,00000,"execute <unnamed>: SELECT address_street as building_street, address_city as building_city, address_state as building_state, address_zipcode as building_zipcode, ST_Distance(the_geom, ST_Transform(PointFromText('POINT(' || $1 || ' ' || $2  || ')', 4269), 32661))*3.2808399 as distance_to_tower
    FROM dim_address_geo r
    WHERE ST_DWithin(transform(PointFromText('POINT(' || $3 || ' ' || $4  || ')', 4269), 32661), r.the_geom, 152.4) ","parameters: $1 = '-76.5949278054326', $2 = '39.3272814709201', $3 = '-76.5949278054326', $4 = '39.3272814709201'",,,,,,,
    2010-09-21 12:00:34.034 EDT,"benkeith","geodjango",24984,"127.0.0.1:33271",4c98d6a0.6198,8,"SELECT",2010-09-21 12:00:32 EDT,1/13,0,LOG,00000,"duration: 17.151 ms",,,,,,,,
    2010-09-21 12:00:34.035 EDT,"benkeith","geodjango",24984,"127.0.0.1:33271",4c98d6a0.6198,9,"PARSE",2010-09-21 12:00:32 EDT,1/14,0,LOG,00000,"duration: 0.232 ms",,,,,,,,
    2010-09-21 12:00:34.036 EDT,"benkeith","geodjango",24984,"127.0.0.1:33271",4c98d6a0.6198,10,"BIND",2010-09-21 12:00:32 EDT,1/14,0,LOG,00000,"duration: 0.992 ms",,,,,,,,
    2010-09-21 12:00:34.036 EDT,"benkeith","geodjango",24984,"127.0.0.1:33271",4c98d6a0.6198,11,"SELECT",2010-09-21 12:00:32 EDT,1/14,0,LOG,00000,"execute <unnamed>: SELECT address_street as building_street, address_city as building_city, address_state as building_state, address_zipcode as building_zipcode, ST_Distance(the_geom, ST_Transform(PointFromText('POINT(' || $1 || ' ' || $2  || ')', 4269), 32661))*3.2808399 as distance_to_tower
    FROM dim_address_geo r
    WHERE ST_DWithin(transform(PointFromText('POINT(' || $3 || ' ' || $4  || ')', 4269), 32661), r.the_geom, 152.4) ","parameters: $1 = '-76.6197362844493', $2 = '39.2851932902502', $3 = '-76.6197362844493', $4 = '39.2851932902502'",,,,,,,
    2010-09-21 12:00:34.038 EDT,"benkeith","geodjango",24984,"127.0.0.1:33271",4c98d6a0.6198,12,"SELECT",2010-09-21 12:00:32 EDT,1/14,0,LOG,00000,"duration: 1.646 ms",,,,,,,,
    2010-09-21 12:00:34.039 EDT,"benkeith","geodjango",24984,"127.0.0.1:33271",4c98d6a0.6198,13,"PARSE",2010-09-21 12:00:32 EDT,1/15,0,LOG,00000,"duration: 0.296 ms",,,,,,,,
    2010-09-21 12:00:34.040 EDT,"benkeith","geodjango",24984,"127.0.0.1:33271",4c98d6a0.6198,14,"BIND",2010-09-21 12:00:32 EDT,1/15,0,LOG,00000,"duration: 0.992 ms",,,,,,,,
    2010-09-21 12:00:34.040 EDT,"benkeith","geodjango",24984,"127.0.0.1:33271",4c98d6a0.6198,15,"SELECT",2010-09-21 12:00:32 EDT,1/15,0,LOG,00000,"execute <unnamed>: SELECT address_street as building_street, address_city as building_city, address_state as building_state, address_zipcode as building_zipcode, ST_Distance(the_geom, ST_Transform(PointFromText('POINT(' || $1 || ' ' || $2  || ')', 4269), 32661))*3.2808399 as distance_to_tower
    FROM dim_address_geo r
    WHERE ST_DWithin(transform(PointFromText('POINT(' || $3 || ' ' || $4  || ')', 4269), 32661), r.the_geom, 152.4) ","parameters: $1 = '-76.6125062117927', $2 = '39.2921433560024', $3 = '-76.6125062117927', $4 = '39.2921433560024'",,,,,,,
    2010-09-21 12:00:34.046 EDT,"benkeith","geodjango",24984,"127.0.0.1:33271",4c98d6a0.6198,16,"SELECT",2010-09-21 12:00:32 EDT,1/15,0,LOG,00000,"duration: 6.251 ms",,,,,,,,
    2010-09-21 12:00:34.047 EDT,"benkeith","geodjango",24984,"127.0.0.1:33271",4c98d6a0.6198,17,"PARSE",2010-09-21 12:00:32 EDT,1/16,0,LOG,00000,"duration: 0.448 ms",,,,,,,,
    2010-09-21 12:00:34.047 EDT,"benkeith","geodjango",24984,"127.0.0.1:33271",4c98d6a0.6198,18,"BIND",2010-09-21 12:00:32 EDT,1/16,0,LOG,00000,"duration: 0.048 ms",,,,,,,,
    2010-09-21 12:00:34.047 EDT,"benkeith","geodjango",24984,"127.0.0.1:33271",4c98d6a0.6198,19,"SELECT",2010-09-21 12:00:32 EDT,1/16,0,LOG,00000,"execute S_1: SELECT address_street as building_street, address_city as building_city, address_state as building_state, address_zipcode as building_zipcode, ST_Distance(the_geom, ST_Transform(PointFromText('POINT(' || $1 || ' ' || $2  || ')', 4269), 32661))*3.2808399 as distance_to_tower
    FROM dim_address_geo r
    WHERE ST_DWithin(transform(PointFromText('POINT(' || $3 || ' ' || $4  || ')', 4269), 32661), r.the_geom, 152.4) ","parameters: $1 = '-76.5943953112787', $2 = '39.285457700409', $3 = '-76.5943953112787', $4 = '39.285457700409'",,,,,,,
    2010-09-21 12:00:59.933 EDT,"benkeith","geodjango",24984,"127.0.0.1:33271",4c98d6a0.6198,20,"SELECT",2010-09-21 12:00:32 EDT,1/16,0,LOG,00000,"duration: 25885.772 ms",,,,,,,,
    2010-09-21 12:00:59.934 EDT,"benkeith","geodjango",24984,"127.0.0.1:33271",4c98d6a0.6198,21,"BIND",2010-09-21 12:00:32 EDT,1/17,0,LOG,00000,"duration: 0.064 ms",,,,,,,,
    2010-09-21 12:00:59.934 EDT,"benkeith","geodjango",24984,"127.0.0.1:33271",4c98d6a0.6198,22,"SELECT",2010-09-21 12:00:32 EDT,1/17,0,LOG,00000,"execute S_1: SELECT address_street as building_street, address_city as building_city, address_state as building_state, address_zipcode as building_zipcode, ST_Distance(the_geom, ST_Transform(PointFromText('POINT(' || $1 || ' ' || $2  || ')', 4269), 32661))*3.2808399 as distance_to_tower
    FROM dim_address_geo r
    WHERE ST_DWithin(transform(PointFromText('POINT(' || $3 || ' ' || $4  || ')', 4269), 32661), r.the_geom, 152.4) ","parameters: $1 = '-76.6120321963502', $2 = '39.2751761452328', $3 = '-76.6120321963502', $4 = '39.2751761452328'",,,,,,,
    2010-09-21 12:01:26.288 EDT,"benkeith","geodjango",24984,"127.0.0.1:33271",4c98d6a0.6198,23,"SELECT",2010-09-21 12:00:32 EDT,1/17,0,LOG,00000,"duration: 26353.977 ms",,,,,,,,
    2010-09-21 12:01:26.289 EDT,"benkeith","geodjango",24984,"127.0.0.1:33271",4c98d6a0.6198,24,"BIND",2010-09-21 12:00:32 EDT,1/18,0,LOG,00000,"duration: 0.059 ms",,,,,,,,
    2010-09-21 12:01:26.289 EDT,"benkeith","geodjango",24984,"127.0.0.1:33271",4c98d6a0.6198,25,"SELECT",2010-09-21 12:00:32 EDT,1/18,0,LOG,00000,"execute S_1: SELECT address_street as building_street, address_city as building_city, address_state as building_state, address_zipcode as building_zipcode, ST_Distance(the_geom, ST_Transform(PointFromText('POINT(' || $1 || ' ' || $2  || ')', 4269), 32661))*3.2808399 as distance_to_tower
    FROM dim_address_geo r
    WHERE ST_DWithin(transform(PointFromText('POINT(' || $3 || ' ' || $4  || ')', 4269), 32661), r.the_geom, 152.4) ","parameters: $1 = '-76.6394356247244', $2 = '39.3291512679247', $3 = '-76.6394356247244', $4 = '39.3291512679247'",,,,,,,
    2010-09-21 12:01:54.230 EDT,"benkeith","geodjango",24984,"127.0.0.1:33271",4c98d6a0.6198,26,"SELECT",2010-09-21 12:00:32 EDT,1/18,0,LOG,00000,"duration: 27941.443 ms",,,,,,,,
    2010-09-21 12:01:54.231 EDT,"benkeith","geodjango",24984,"127.0.0.1:33271",4c98d6a0.6198,27,"BIND",2010-09-21 12:00:32 EDT,1/19,0,LOG,00000,"duration: 0.069 ms",,,,,,,,
    2010-09-21 12:01:54.231 EDT,"benkeith","geodjango",24984,"127.0.0.1:33271",4c98d6a0.6198,28,"SELECT",2010-09-21 12:00:32 EDT,1/19,0,LOG,00000,"execute S_1: SELECT address_street as building_street, address_city as building_city, address_state as building_state, address_zipcode as building_zipcode, ST_Distance(the_geom, ST_Transform(PointFromText('POINT(' || $1 || ' ' || $2  || ')', 4269), 32661))*3.2808399 as distance_to_tower
    FROM dim_address_geo r
    WHERE ST_DWithin(transform(PointFromText('POINT(' || $3 || ' ' || $4  || ')', 4269), 32661), r.the_geom, 152.4) ","parameters: $1 = '-76.6073208536814', $2 = '39.2972833106504', $3 = '-76.6073208536814', $4 = '39.2972833106504'",,,,,,,
    I can post config parameters if that would be helpful.

    Thanks a lot,
    -Ben Keith

    Edit: I updated the jdbc drivers to the latest available for the postgresql server I am running (8.4) and the problem has not changed. If it is the ETL software, why would it cause the query duration to be so long in the logs? If it is a postgresql problem, ????
    Last edited by benkeith; 09-22-10 at 11:08. Reason: new info

Posting Permissions

  • You may not post new threads
  • You may not post replies
  • You may not post attachments
  • You may not edit your posts
  •