Thread: postgres 9.6: insert into select finishes only in pgadmin not psql
If this is a common question or an article exists, please let me know. I couldn't find anything specific about it in stack overflow questions or postgres/psql documentation.
This is in PostgreSQL 9.6.
I am trying to figure out how to debug an issue where a function 'import_wss' called through pgadmin4 will complete but not through psql.
The function is simply a wrapper around an INSERT INTO SELECT that copies about 800k rows with some id and string conversions. This completes in about 1min through pgadmin, but does not finish when run through psql.
There are cases where the psql call does finish, but it is rare and after running several tests I can't say what conditions there are. I am running with a simple select like:
psql -c 'select import_wss()'
The only relevant issues I've run across are cases where there are multiple inserts separated by semi-colons. However, this is a single insert and query logging shows the same query run by both pgadmin and psql.
There is no other load on the db. I can reproduce this issue right after creating the db and running the script.
corey
Corey Taylor <corey.taylor.fl@gmail.com> writes:
> I am trying to figure out how to debug an issue where a function
> 'import_wss' called through pgadmin4 will complete but not through psql.
First thing I'd look at is whether it's the same execution environment
in both cases, eg same search_path.
You could try doing EXPLAIN rather than running the query outright,
too, to see if you get identical plans. (Although if the performance
issue is down inside the function, that might not help much.)
regards, tom lane
First thing I'd look at is whether it's the same execution environment
in both cases, eg same search_path.
As far as I can tell, it's the same execution environment, same search_path and same user.
I found after testing other situations, that the psql command would always finish as expected after canceling the first query that ran too long. I was able to reproduce this scenario with psql and pgadmin4 with various combinations.
Any suggestions on what that would indicate? The canceled query does not complete as there are no rows and no duplicate errors when running the second time.
corey
Corey Taylor <corey.taylor.fl@gmail.com> writes:
> I found after testing other situations, that the psql command would always
> finish as expected after canceling the first query that ran too long. I
> was able to reproduce this scenario with psql and pgadmin4 with various
> combinations.
Well, that's just weird.
It's well known that the second run of a query can be much faster due
to having fully-populated caches to draw on, but you seem to have a
case that may go beyond that. Maybe check for waiting on a lock?
It'd be useful to look in pg_stat_activity and/or top(1) while the
initial query is running, to see if it seems to be eating CPU or
is blocked on some condition. (I forget how thorough the
wait_event coverage is in 9.6, but it does at least have those
columns.)
Can you create a self-contained test case that acts like this?
regards, tom lane
On 9/23/19 12:07 AM, Corey Taylor wrote: > First thing I'd look at is whether it's the same execution environment > in both cases, eg same search_path. > > > As far as I can tell, it's the same execution environment, same > search_path and same user. > > I found after testing other situations, that the psql command would > always finish as expected after canceling the first query that ran too > long. I was able to reproduce this scenario with psql and pgadmin4 with > various combinations. > > Any suggestions on what that would indicate? The canceled query does > not complete as there are no rows and no duplicate errors when running > the second time. Can we see the actual function/query? Also the schema of the table(s) involved? > > corey -- Adrian Klaver adrian.klaver@aklaver.com
On Mon, Sep 23, 2019 at 8:57 AM Tom Lane <tgl@sss.pgh.pa.us> wrote:
Maybe check for waiting on a lock?
It'd be useful to look in pg_stat_activity and/or top(1) while the
initial query is running, to see if it seems to be eating CPU or
is blocked on some condition.
I think this will provide information that makes it seem less weird.
With your suggestion, I monitored postgres via top and pg_stat_activity in the various scenarios and found that an autovacuum was triggering which covered tables used in the insert into select. What seems to be happening is the autovacuum takes just about the same time as I give the query to run before giving up on it. The next time I run the query, the autovacuum is complete and the query runs normally.
Of course, I'd like to understand why the query never finishes.
when autovacuum is running:
PID PPID USER STAT VSZ %VSZ CPU %CPU COMMAND
38 1 postgres R 158m 8% 1 50% postgres: revwaste portal-local 172.19.0.5(39956) SELECT36 1 postgres S 171m 9% 0 0% postgres: autovacuum worker process portal-local
34 1 postgres S 186m 9% 0 0% postgres: autovacuum worker process portal-local
after autovacuum finishes and during remaining soft-lock:
PID PPID USER STAT VSZ %VSZ CPU %CPU COMMAND
45 1 postgres R 259m 13% 0 50% postgres: revwaste portal-local 172.19.0.5(39962) SELECT
20 1 postgres S 153m 8% 1 0% postgres: writer process
22 1 postgres S 153m 8% 0 0% postgres: autovacuum launcher process
45 1 postgres R 259m 13% 0 50% postgres: revwaste portal-local 172.19.0.5(39962) SELECT
20 1 postgres S 153m 8% 1 0% postgres: writer process
22 1 postgres S 153m 8% 0 0% postgres: autovacuum launcher process
Same for pg_stat_activity:
| backend_start | xact_start | query_start | state_change | wait_event_type | wait_event | state | backend_xid | backend_xmin | query
-------+--------------+-----+----------+----------+------------------+-------------+-----------------+-------------+-------------------------------+-------------------------------+-------------------------------+------------------------------
| 2019-09-23 20:29:45.127527+00 | 2019-09-23 20:29:45.12886+00 | 2019-09-23 20:29:45.12886+00 | 2019-09-23 20:29:45.128861+00 | | | active | 808 | 808 | select import_wss()
| 2019-09-23 20:30:01.624853+00 | 2019-09-23 20:30:58.047317+00 | 2019-09-23 20:30:58.047317+00 | 2019-09-23 20:30:58.047318+00 | | | active | | 808 | autovacuum: ANALYZE wss.RowCoding
| 2019-09-23 20:31:01.644824+00 | 2019-09-23 20:31:01.666711+00 | 2019-09-23 20:31:01.666711+00 | 2019-09-23 20:31:01.666712+00 | | | active | | 808 | autovacuum: ANALYZE wss.WSSData
| 2019-09-23 20:31:14.101808+00 | 2019-09-23 20:31:14.103306+00 | 2019-09-23 20:31:14.103306+00 | 2019-09-23 20:31:14.103307+00 | | | active | | 808 | select * from pg_stat_activity
(4 rows)
| backend_start | xact_start | query_start | state_change | wait_event_type | wait_event | state | backend_xid | backend_xmin | query
-------+--------------+-----+----------+----------+------------------+-------------+-----------------+-------------+-------------------------------+-------------------------------+-------------------------------+-------------------------------
| 2019-09-23 20:29:45.127527+00 | 2019-09-23 20:29:45.12886+00 | 2019-09-23 20:29:45.12886+00 | 2019-09-23 20:29:45.128861+00 | | | active | 808 | 808 | select import_wss()
| 2019-09-23 20:34:21.01283+00 | 2019-09-23 20:34:21.014473+00 | 2019-09-23 20:34:21.014473+00 | 2019-09-23 20:34:21.014475+00 | | | active | | 808 | select * from pg_stat_activity
(2 rows)
-------+--------------+-----+----------+----------+------------------+-------------+-----------------+-------------+-------------------------------+-------------------------------+-------------------------------+------------------------------
| 2019-09-23 20:29:45.127527+00 | 2019-09-23 20:29:45.12886+00 | 2019-09-23 20:29:45.12886+00 | 2019-09-23 20:29:45.128861+00 | | | active | 808 | 808 | select import_wss()
| 2019-09-23 20:30:01.624853+00 | 2019-09-23 20:30:58.047317+00 | 2019-09-23 20:30:58.047317+00 | 2019-09-23 20:30:58.047318+00 | | | active | | 808 | autovacuum: ANALYZE wss.RowCoding
| 2019-09-23 20:31:01.644824+00 | 2019-09-23 20:31:01.666711+00 | 2019-09-23 20:31:01.666711+00 | 2019-09-23 20:31:01.666712+00 | | | active | | 808 | autovacuum: ANALYZE wss.WSSData
| 2019-09-23 20:31:14.101808+00 | 2019-09-23 20:31:14.103306+00 | 2019-09-23 20:31:14.103306+00 | 2019-09-23 20:31:14.103307+00 | | | active | | 808 | select * from pg_stat_activity
(4 rows)
| backend_start | xact_start | query_start | state_change | wait_event_type | wait_event | state | backend_xid | backend_xmin | query
-------+--------------+-----+----------+----------+------------------+-------------+-----------------+-------------+-------------------------------+-------------------------------+-------------------------------+-------------------------------
| 2019-09-23 20:29:45.127527+00 | 2019-09-23 20:29:45.12886+00 | 2019-09-23 20:29:45.12886+00 | 2019-09-23 20:29:45.128861+00 | | | active | 808 | 808 | select import_wss()
| 2019-09-23 20:34:21.01283+00 | 2019-09-23 20:34:21.014473+00 | 2019-09-23 20:34:21.014473+00 | 2019-09-23 20:34:21.014475+00 | | | active | | 808 | select * from pg_stat_activity
(2 rows)
Can you create a self-contained test case that acts like this?
I can try to duplicate it if this doesn't provide the details needed.
corey
On Mon, Sep 23, 2019 at 9:22 AM Adrian Klaver <adrian.klaver@aklaver.com> wrote:
Can we see the actual function/query?
Also the schema of the table(s) involved?
Of course. This was added to pull some data from legacy db tables into something we could query while converting the process that populates the legacy db. These are rather long. I'll spare you the details of the other tables it joins as they are basically id <=> name pairs for the most part.
This isn't meant to run often, but it does need to be run every time the legacy db data is pulled over.
Import Function:
CREATE OR REPLACE FUNCTION import_wss()
RETURNS void AS $$
INSERT INTO wss_entries (
is_historical,
historical_path,
wss_import_row_index,
service_date,
original_sid,
client_id,
client_site_id,
material_group_id,
material_category_id,
material_id,
material_outcome_id,
targeted,
goal_percent,
weight_pounds,
old_vendor_name,
new_vendor_name,
vendor_id,
vendor_site_id,
old_service_type,
new_service_type,
old_quantity,
old_size,
old_frequency,
old_price,
old_market_index,
old_service_per_month,
old_units_per_haul,
old_avg_monthly_cost,
new_quantity,
new_size,
new_frequency,
new_price,
new_market_index,
new_service_per_month,
new_units_per_haul,
new_avg_monthly_cost,
is_haul,
haul_unit_id,
service_conversion_id,
num_hauls_per_weight,
compaction_ratio,
unit_weight,
full_percent,
benchmark_hauling_cost,
total_monthly_cost,
gross_savings,
month_of_shared_savings,
wr_fees,
net_savings,
new_account_number,
contract_expiration,
scheduled_service_days
) SELECT
true,
w."Path",
w."RowNum",
w."WSSDate"::date,
CASE
WHEN client_sites.id IS null THEN TRIM(w."SID")
ELSE null
END,
client_sites.client_id,
client_sites.id,
material_groups.id,
material_categories.id,
materials.id,
material_outcomes.id,
w."Targeted" = 'True',
w."Goal Percentage",
w."Total Pounds",
NULLIF(w."Old Vendor ", ''),
NULLIF(w."New Vendor", ''),
vendor_sites.vendor_id,
vendor_sites.id,
NULLIF(w."Old Service Description", ''),
NULLIF(w."New Service Description", ''),
NULLIF(w."Old Quan", ''),
NULLIF(w."Old Size", ''),
NULLIF(w."Old Freq", ''),
CASE
WHEN w."Old Price " ~ '^[0-9\-]+[0-9\.\-E]*$' THEN w."Old Price "::float
ELSE 0::float
END,
CASE
WHEN w."Old Market Index" ~ '^[0-9\-]+[0-9\.\-E]*$' THEN w."Old Market Index"::float
ELSE 0::float
END,
CASE
WHEN w."Old Service Per Month" ~ '^[0-9\-]+[0-9\.\-E]*$' THEN w."Old Service Per Month"::float
ELSE 0::float
END,
CASE
WHEN w."Old Tons Per Haul" ~ '^[0-9\-]+[0-9\.\-E]*$' THEN w."Old Tons Per Haul"::float
ELSE 0::float
END,
CASE
WHEN w."Old Monthly Cost" ~ '^[0-9\-]+[0-9\.\-E]*$' THEN w."Old Monthly Cost"::float
ELSE 0::float
END,
NULLIF(w."New Quan", ''),
NULLIF(w."New Size", ''),
NULLIF(w."New Freq", ''),
CASE
WHEN w."New Price " ~ '^[0-9\-]+[0-9\.\-E]*$' THEN w."New Price "::float
ELSE 0::float
END,
CASE
WHEN w."New Market Index" ~ '^[0-9\-]+[0-9\.\-E]*$' THEN w."New Market Index"::float
ELSE 0::float
END,
CASE
WHEN w."New Service Per Month" ~ '^[0-9\-]+[0-9\.\-E]*$' THEN w."New Service Per Month"::float
ELSE 0::float
END,
CASE
WHEN w."New Tons Per haul" ~ '^[0-9\-]+[0-9\.\-E]*$' THEN w."New Tons Per haul"::float
ELSE 0::float
END,
CASE
WHEN w."New Monthly Cost" ~ '^[0-9\-]+[0-9\.\-E]*$' THEN w."New Monthly Cost"::float
ELSE 0::float
END,
r."LineType" = 'Haul',
haul_units.id,
service_conversions.id,
CASE
WHEN w."hauls coorelating to this weight" ~ '^[0-9\-]+[0-9\.\-E]*$' THEN w."hauls coorelating to this weight"::float
ELSE 0::float
END,
NULLIF(w."Estimated Compaction Ratio", ''),
CASE
WHEN w."Unit weight assigned to waste" ~ '^[0-9\-]+[0-9\.\-E]*$' THEN w."Unit weight assigned to waste"::float
ELSE 0::float
END,
CASE
WHEN w."Pct Full based on last survey" ~ '^[0-9\-]+[0-9\.\-E]*$' THEN w."Pct Full based on last survey"::float
ELSE 0::float
END,
CASE
WHEN w."Benchmark Costs" ~ '^[0-9\-]+[0-9\.\-E]*$' THEN w."Benchmark Costs"::float
ELSE 0::float
END,
CASE
WHEN w."Total Monthly Costs" ~ '^[0-9\-]+[0-9\.\-E]*$' THEN w."Total Monthly Costs"::float
ELSE 0::float
END,
CASE
WHEN w."Gross Savings" ~ '^[0-9\-]+[0-9\.\-E]*$' THEN w."Gross Savings"::float
ELSE 0::float
END,
CASE
WHEN w."Month of Shared Savings" ~ '^[0-9\-]+[0-9\.\-E]*$' THEN w."Month of Shared Savings"::float
ELSE 0::float
END,
CASE
WHEN w."WR Fees" ~ '^[0-9\-]+[0-9\.\-E]*$' THEN w."WR Fees"::float
ELSE 0::float
END,
CASE
WHEN w."Net Savings" ~ '^[0-9\-]+[0-9\.\-E]*$' THEN w."Net Savings"::float
ELSE 0::float
END,
NULLIF(w."New Account Number", ''),
NULLIF(w."Current Contract Expiration Date", ''),
NULLIF(w."Current Scheduled Service Days", '')
FROM wss."WSSData" w
LEFT OUTER JOIN wss."RowCoding" r ON r."Path" = w."Path" AND
r."RowNum" = w."RowNum" AND r."WSSDate" = w."WSSDate"
LEFT OUTER JOIN client_sites ON client_sites.original_sid = TRIM(w."SID")
LEFT OUTER JOIN material_groups ON material_groups.name = w."Material Group"
LEFT OUTER JOIN material_categories ON material_categories.name = w."Material Category"
AND material_categories.material_group_id = material_groups.id
LEFT OUTER JOIN materials ON materials.name = w."Material Description"
AND materials.material_category_id = material_categories.id
LEFT OUTER JOIN material_outcomes ON material_outcomes.name = w."Material Outcome"
LEFT OUTER JOIN haul_units ON haul_units.name = w."New Units Description"
LEFT OUTER JOIN service_conversions ON service_conversions.name = w."Conversion Code"
LEFT OUTER JOIN vendor_sites ON vendor_sites.id = w."vid"
WHERE w."SID" IS NOT null;
$$ LANGUAGE SQL;
RETURNS void AS $$
INSERT INTO wss_entries (
is_historical,
historical_path,
wss_import_row_index,
service_date,
original_sid,
client_id,
client_site_id,
material_group_id,
material_category_id,
material_id,
material_outcome_id,
targeted,
goal_percent,
weight_pounds,
old_vendor_name,
new_vendor_name,
vendor_id,
vendor_site_id,
old_service_type,
new_service_type,
old_quantity,
old_size,
old_frequency,
old_price,
old_market_index,
old_service_per_month,
old_units_per_haul,
old_avg_monthly_cost,
new_quantity,
new_size,
new_frequency,
new_price,
new_market_index,
new_service_per_month,
new_units_per_haul,
new_avg_monthly_cost,
is_haul,
haul_unit_id,
service_conversion_id,
num_hauls_per_weight,
compaction_ratio,
unit_weight,
full_percent,
benchmark_hauling_cost,
total_monthly_cost,
gross_savings,
month_of_shared_savings,
wr_fees,
net_savings,
new_account_number,
contract_expiration,
scheduled_service_days
) SELECT
true,
w."Path",
w."RowNum",
w."WSSDate"::date,
CASE
WHEN client_sites.id IS null THEN TRIM(w."SID")
ELSE null
END,
client_sites.client_id,
client_sites.id,
material_groups.id,
material_categories.id,
materials.id,
material_outcomes.id,
w."Targeted" = 'True',
w."Goal Percentage",
w."Total Pounds",
NULLIF(w."Old Vendor ", ''),
NULLIF(w."New Vendor", ''),
vendor_sites.vendor_id,
vendor_sites.id,
NULLIF(w."Old Service Description", ''),
NULLIF(w."New Service Description", ''),
NULLIF(w."Old Quan", ''),
NULLIF(w."Old Size", ''),
NULLIF(w."Old Freq", ''),
CASE
WHEN w."Old Price " ~ '^[0-9\-]+[0-9\.\-E]*$' THEN w."Old Price "::float
ELSE 0::float
END,
CASE
WHEN w."Old Market Index" ~ '^[0-9\-]+[0-9\.\-E]*$' THEN w."Old Market Index"::float
ELSE 0::float
END,
CASE
WHEN w."Old Service Per Month" ~ '^[0-9\-]+[0-9\.\-E]*$' THEN w."Old Service Per Month"::float
ELSE 0::float
END,
CASE
WHEN w."Old Tons Per Haul" ~ '^[0-9\-]+[0-9\.\-E]*$' THEN w."Old Tons Per Haul"::float
ELSE 0::float
END,
CASE
WHEN w."Old Monthly Cost" ~ '^[0-9\-]+[0-9\.\-E]*$' THEN w."Old Monthly Cost"::float
ELSE 0::float
END,
NULLIF(w."New Quan", ''),
NULLIF(w."New Size", ''),
NULLIF(w."New Freq", ''),
CASE
WHEN w."New Price " ~ '^[0-9\-]+[0-9\.\-E]*$' THEN w."New Price "::float
ELSE 0::float
END,
CASE
WHEN w."New Market Index" ~ '^[0-9\-]+[0-9\.\-E]*$' THEN w."New Market Index"::float
ELSE 0::float
END,
CASE
WHEN w."New Service Per Month" ~ '^[0-9\-]+[0-9\.\-E]*$' THEN w."New Service Per Month"::float
ELSE 0::float
END,
CASE
WHEN w."New Tons Per haul" ~ '^[0-9\-]+[0-9\.\-E]*$' THEN w."New Tons Per haul"::float
ELSE 0::float
END,
CASE
WHEN w."New Monthly Cost" ~ '^[0-9\-]+[0-9\.\-E]*$' THEN w."New Monthly Cost"::float
ELSE 0::float
END,
r."LineType" = 'Haul',
haul_units.id,
service_conversions.id,
CASE
WHEN w."hauls coorelating to this weight" ~ '^[0-9\-]+[0-9\.\-E]*$' THEN w."hauls coorelating to this weight"::float
ELSE 0::float
END,
NULLIF(w."Estimated Compaction Ratio", ''),
CASE
WHEN w."Unit weight assigned to waste" ~ '^[0-9\-]+[0-9\.\-E]*$' THEN w."Unit weight assigned to waste"::float
ELSE 0::float
END,
CASE
WHEN w."Pct Full based on last survey" ~ '^[0-9\-]+[0-9\.\-E]*$' THEN w."Pct Full based on last survey"::float
ELSE 0::float
END,
CASE
WHEN w."Benchmark Costs" ~ '^[0-9\-]+[0-9\.\-E]*$' THEN w."Benchmark Costs"::float
ELSE 0::float
END,
CASE
WHEN w."Total Monthly Costs" ~ '^[0-9\-]+[0-9\.\-E]*$' THEN w."Total Monthly Costs"::float
ELSE 0::float
END,
CASE
WHEN w."Gross Savings" ~ '^[0-9\-]+[0-9\.\-E]*$' THEN w."Gross Savings"::float
ELSE 0::float
END,
CASE
WHEN w."Month of Shared Savings" ~ '^[0-9\-]+[0-9\.\-E]*$' THEN w."Month of Shared Savings"::float
ELSE 0::float
END,
CASE
WHEN w."WR Fees" ~ '^[0-9\-]+[0-9\.\-E]*$' THEN w."WR Fees"::float
ELSE 0::float
END,
CASE
WHEN w."Net Savings" ~ '^[0-9\-]+[0-9\.\-E]*$' THEN w."Net Savings"::float
ELSE 0::float
END,
NULLIF(w."New Account Number", ''),
NULLIF(w."Current Contract Expiration Date", ''),
NULLIF(w."Current Scheduled Service Days", '')
FROM wss."WSSData" w
LEFT OUTER JOIN wss."RowCoding" r ON r."Path" = w."Path" AND
r."RowNum" = w."RowNum" AND r."WSSDate" = w."WSSDate"
LEFT OUTER JOIN client_sites ON client_sites.original_sid = TRIM(w."SID")
LEFT OUTER JOIN material_groups ON material_groups.name = w."Material Group"
LEFT OUTER JOIN material_categories ON material_categories.name = w."Material Category"
AND material_categories.material_group_id = material_groups.id
LEFT OUTER JOIN materials ON materials.name = w."Material Description"
AND materials.material_category_id = material_categories.id
LEFT OUTER JOIN material_outcomes ON material_outcomes.name = w."Material Outcome"
LEFT OUTER JOIN haul_units ON haul_units.name = w."New Units Description"
LEFT OUTER JOIN service_conversions ON service_conversions.name = w."Conversion Code"
LEFT OUTER JOIN vendor_sites ON vendor_sites.id = w."vid"
WHERE w."SID" IS NOT null;
$$ LANGUAGE SQL;
Source Table:
CREATE TABLE wss."WSSData"
("Path" character varying(255),
"RowNum" integer,
"WSSDate" timestamp without time zone,
"SID" character varying(255),
"Client Name" character varying(255),
"Location Name" character varying(255),
"Site Type" character varying(255),
"Region" character varying(255),
"Company Code" character varying(255),
"Accounting Code" character varying(255),
"Cost Center Code" character varying(255),
"Client Address" character varying(255),
"Client City" character varying(255),
"Client State" character varying(255),
"Client Zip" character varying(255),
"Client Contact" character varying(255),
"Client Phone" character varying(255),
"Client Cell" character varying(255),
"Client Fax" character varying(255),
"Client Email" character varying(255),
"Old Vendor " character varying(255),
"Old Vendor Contact" character varying(255),
"Old Vendor Address" character varying(255),
"Old Vendor City" character varying(255),
"Old Vendor State" character varying(255),
"Old Vendor Zip Code" character varying(255),
"Old Vendor Phone" character varying(255),
"Old Vendor Cell" character varying(255),
"Old Vendor Fax" character varying(255),
"Old Vendor Email" character varying(255),
"Old Account Number" character varying(255),
"Old Scheduled Service Days" character varying(255),
"Old Service Description" character varying(255),
"Old Contract Expire Date" character varying(255),
"Old Quan" character varying(255),
"Old Size" character varying(255),
"Old Freq" character varying(255),
"Old Price " character varying(255),
"Old Market Index" character varying(255),
"Old Service Per Month" character varying(255),
"Old Tons Per Haul" character varying(255),
"Old Monthly Cost" character varying(255),
"Service History Period" character varying(255),
"Original Contract Expiration Date" character varying(255),
"Renewal Window" character varying(255),
"Date LOA Received to Prevent Original Contract Renewal" character varying(255),
"Master Spreadsheet Creation and Research Comments" character varying(255),
"New Vendor" character varying(255),
"New Vendor Contact" character varying(255),
"New Vendor Address" character varying(255),
"New Vendor City" character varying(255),
"New Vendor State" character varying(255),
"New Vendor Zip Code" character varying(255),
"New Vendor Phone" character varying(255),
"New Vendor Cell" character varying(255),
"New Vendor Fax" character varying(255),
"New Vendor Email" character varying(255),
"New Account Number" character varying(255),
"Current Scheduled Service Days" character varying(255),
"Off Hour instruction comments for service issues" character varying(255),
"Current Contract Expiration Date" character varying(255),
"New Service Description" character varying(255),
"Conversion Code" character varying(255),
"hauls coorelating to this weight" character varying(255),
"Estimated Compaction Ratio" character varying(255),
"Unit weight assigned to waste" character varying(255),
"Pct Full based on last survey" character varying(255),
"Section on Sustainability Report" character varying(255),
"Material Group" character varying(255),
"Material Category" character varying(255),
"Material Outcome" character varying(255),
"New Quan" character varying(255),
"New Size" character varying(255),
"New Freq" character varying(255),
"New Price " character varying(255),
"New Market Index" character varying(255),
"New Service Per Month" character varying(255),
"New Tons Per haul" character varying(255),
"New Monthly Cost" character varying(255),
"Benchmark Costs" character varying(255),
"Total Monthly Costs" character varying(255),
"Gross Savings" character varying(255),
"Month of Shared Savings" character varying(255),
"WR Fees" character varying(255),
"Net Savings" character varying(255),
"Implementation and Maintenance Comments" character varying(255),
"Total Pounds" double precision,
"Material Description" character varying(70),
"Targeted" character varying(5),
vid integer,
"New Vendor District" character varying(255),
"New Units Description" character varying(50),
"Goal Percentage" double precision
)
Destination Table:
CREATE TABLE public.wss_entries
(
id integer NOT NULL DEFAULT nextval('wss_entries_id_seq'::regclass),
is_historical boolean NOT NULL,
historical_path text,
wss_import_id integer,
wss_import_row_index integer NOT NULL,
service_date date NOT NULL,
original_sid text,
client_id integer,
client_site_id integer,
material_group_id integer,
material_category_id integer,
material_id integer,
material_outcome_id integer,
targeted boolean,
goal_percent double precision,
weight_pounds double precision,
old_vendor_name text,
new_vendor_name text,
vendor_id integer,
vendor_site_id integer,
old_service_type text,
new_service_type text,
old_quantity text,
old_size text,
old_frequency text,
old_price double precision,
old_market_index double precision,
old_service_per_month double precision,
old_units_per_haul double precision,
old_avg_monthly_cost double precision,
new_quantity text,
new_size text,
new_frequency text,
new_price double precision,
new_market_index double precision,
new_service_per_month double precision,
new_units_per_haul double precision,
new_avg_monthly_cost double precision,
is_haul boolean,
haul_unit_id integer,
service_conversion_id integer,
num_hauls_per_weight double precision,
compaction_ratio text,
unit_weight double precision,
full_percent double precision,
benchmark_hauling_cost double precision,
total_monthly_cost double precision,
gross_savings double precision,
month_of_shared_savings integer,
wr_fees double precision,
net_savings double precision,
new_account_number text,
contract_expiration text,
scheduled_service_days text,
invoicing_comments text,
CONSTRAINT wss_entries_pkey PRIMARY KEY (id),
CONSTRAINT wss_entries_client_id_fkey FOREIGN KEY (client_id)
REFERENCES public.clients (id) MATCH SIMPLE
ON UPDATE NO ACTION
ON DELETE NO ACTION,
CONSTRAINT wss_entries_client_site_id_fkey FOREIGN KEY (client_site_id)
REFERENCES public.client_sites (id) MATCH SIMPLE
ON UPDATE NO ACTION
ON DELETE NO ACTION,
CONSTRAINT wss_entries_haul_unit_id_fkey FOREIGN KEY (haul_unit_id)
REFERENCES public.haul_units (id) MATCH SIMPLE
ON UPDATE NO ACTION
ON DELETE NO ACTION,
CONSTRAINT wss_entries_material_category_id_fkey FOREIGN KEY (material_category_id)
REFERENCES public.material_categories (id) MATCH SIMPLE
ON UPDATE NO ACTION
ON DELETE NO ACTION,
CONSTRAINT wss_entries_material_group_id_fkey FOREIGN KEY (material_group_id)
REFERENCES public.material_groups (id) MATCH SIMPLE
ON UPDATE NO ACTION
ON DELETE NO ACTION,
CONSTRAINT wss_entries_material_id_fkey FOREIGN KEY (material_id)
REFERENCES public.materials (id) MATCH SIMPLE
ON UPDATE NO ACTION
ON DELETE NO ACTION,
CONSTRAINT wss_entries_material_outcome_id_fkey FOREIGN KEY (material_outcome_id)
REFERENCES public.material_outcomes (id) MATCH SIMPLE
ON UPDATE NO ACTION
ON DELETE NO ACTION,
CONSTRAINT wss_entries_service_conversion_id_fkey FOREIGN KEY (service_conversion_id)
REFERENCES public.service_conversions (id) MATCH SIMPLE
ON UPDATE NO ACTION
ON DELETE NO ACTION,
CONSTRAINT wss_entries_vendor_id_fkey FOREIGN KEY (vendor_id)
REFERENCES public.vendors (id) MATCH SIMPLE
ON UPDATE NO ACTION
ON DELETE NO ACTION,
CONSTRAINT wss_entries_vendor_site_id_fkey FOREIGN KEY (vendor_site_id)
REFERENCES public.vendor_sites (id) MATCH SIMPLE
ON UPDATE NO ACTION
ON DELETE NO ACTION,
CONSTRAINT wss_entries_wss_import_id_fkey FOREIGN KEY (wss_import_id)
REFERENCES public.wss_imports (id) MATCH SIMPLE
ON UPDATE NO ACTION
ON DELETE NO ACTION,
CONSTRAINT wss_entries_check CHECK (client_site_id IS NOT NULL OR original_sid IS NOT NULL),
CONSTRAINT wss_entries_check1 CHECK (wss_import_id IS NOT NULL OR is_historical)
)
(
id integer NOT NULL DEFAULT nextval('wss_entries_id_seq'::regclass),
is_historical boolean NOT NULL,
historical_path text,
wss_import_id integer,
wss_import_row_index integer NOT NULL,
service_date date NOT NULL,
original_sid text,
client_id integer,
client_site_id integer,
material_group_id integer,
material_category_id integer,
material_id integer,
material_outcome_id integer,
targeted boolean,
goal_percent double precision,
weight_pounds double precision,
old_vendor_name text,
new_vendor_name text,
vendor_id integer,
vendor_site_id integer,
old_service_type text,
new_service_type text,
old_quantity text,
old_size text,
old_frequency text,
old_price double precision,
old_market_index double precision,
old_service_per_month double precision,
old_units_per_haul double precision,
old_avg_monthly_cost double precision,
new_quantity text,
new_size text,
new_frequency text,
new_price double precision,
new_market_index double precision,
new_service_per_month double precision,
new_units_per_haul double precision,
new_avg_monthly_cost double precision,
is_haul boolean,
haul_unit_id integer,
service_conversion_id integer,
num_hauls_per_weight double precision,
compaction_ratio text,
unit_weight double precision,
full_percent double precision,
benchmark_hauling_cost double precision,
total_monthly_cost double precision,
gross_savings double precision,
month_of_shared_savings integer,
wr_fees double precision,
net_savings double precision,
new_account_number text,
contract_expiration text,
scheduled_service_days text,
invoicing_comments text,
CONSTRAINT wss_entries_pkey PRIMARY KEY (id),
CONSTRAINT wss_entries_client_id_fkey FOREIGN KEY (client_id)
REFERENCES public.clients (id) MATCH SIMPLE
ON UPDATE NO ACTION
ON DELETE NO ACTION,
CONSTRAINT wss_entries_client_site_id_fkey FOREIGN KEY (client_site_id)
REFERENCES public.client_sites (id) MATCH SIMPLE
ON UPDATE NO ACTION
ON DELETE NO ACTION,
CONSTRAINT wss_entries_haul_unit_id_fkey FOREIGN KEY (haul_unit_id)
REFERENCES public.haul_units (id) MATCH SIMPLE
ON UPDATE NO ACTION
ON DELETE NO ACTION,
CONSTRAINT wss_entries_material_category_id_fkey FOREIGN KEY (material_category_id)
REFERENCES public.material_categories (id) MATCH SIMPLE
ON UPDATE NO ACTION
ON DELETE NO ACTION,
CONSTRAINT wss_entries_material_group_id_fkey FOREIGN KEY (material_group_id)
REFERENCES public.material_groups (id) MATCH SIMPLE
ON UPDATE NO ACTION
ON DELETE NO ACTION,
CONSTRAINT wss_entries_material_id_fkey FOREIGN KEY (material_id)
REFERENCES public.materials (id) MATCH SIMPLE
ON UPDATE NO ACTION
ON DELETE NO ACTION,
CONSTRAINT wss_entries_material_outcome_id_fkey FOREIGN KEY (material_outcome_id)
REFERENCES public.material_outcomes (id) MATCH SIMPLE
ON UPDATE NO ACTION
ON DELETE NO ACTION,
CONSTRAINT wss_entries_service_conversion_id_fkey FOREIGN KEY (service_conversion_id)
REFERENCES public.service_conversions (id) MATCH SIMPLE
ON UPDATE NO ACTION
ON DELETE NO ACTION,
CONSTRAINT wss_entries_vendor_id_fkey FOREIGN KEY (vendor_id)
REFERENCES public.vendors (id) MATCH SIMPLE
ON UPDATE NO ACTION
ON DELETE NO ACTION,
CONSTRAINT wss_entries_vendor_site_id_fkey FOREIGN KEY (vendor_site_id)
REFERENCES public.vendor_sites (id) MATCH SIMPLE
ON UPDATE NO ACTION
ON DELETE NO ACTION,
CONSTRAINT wss_entries_wss_import_id_fkey FOREIGN KEY (wss_import_id)
REFERENCES public.wss_imports (id) MATCH SIMPLE
ON UPDATE NO ACTION
ON DELETE NO ACTION,
CONSTRAINT wss_entries_check CHECK (client_site_id IS NOT NULL OR original_sid IS NOT NULL),
CONSTRAINT wss_entries_check1 CHECK (wss_import_id IS NOT NULL OR is_historical)
)
corey
On 9/23/19 1:58 PM, Corey Taylor wrote: > On Mon, Sep 23, 2019 at 8:57 AM Tom Lane <tgl@sss.pgh.pa.us > <mailto:tgl@sss.pgh.pa.us>> wrote: > > Maybe check for waiting on a lock? > It'd be useful to look in pg_stat_activity and/or top(1) while the > initial query is running, to see if it seems to be eating CPU or > is blocked on some condition. > > > I think this will provide information that makes it seem less weird. > > With your suggestion, I monitored postgres via top and pg_stat_activity > in the various scenarios and found that an autovacuum was triggering > which covered tables used in the insert into select. What seems to be > happening is the autovacuum takes just about the same time as I give the > query to run before giving up on it. The next time I run the query, the > autovacuum is complete and the query runs normally. Hmm, are there triggers on wss_entries that are UPDATEing/DELETEing entries elsewhere? > > Of course, I'd like to understand why the query never finishes. > > when autovacuum is running: > PID PPID USER STAT VSZ %VSZ CPU %CPU COMMAND > 38 1 postgres R 158m 8% 1 50% postgres: revwaste > portal-local 172.19.0.5(39956) SELECT > 36 1 postgres S 171m 9% 0 0% postgres: autovacuum > worker process portal-local > 34 1 postgres S 186m 9% 0 0% postgres: autovacuum > worker process portal-local > > after autovacuum finishes and during remaining soft-lock: > PID PPID USER STAT VSZ %VSZ CPU %CPU COMMAND > 45 1 postgres R 259m 13% 0 50% postgres: revwaste > portal-local 172.19.0.5(39962) SELECT > 20 1 postgres S 153m 8% 1 0% postgres: writer process > 22 1 postgres S 153m 8% 0 0% postgres: autovacuum > launcher process > > Same for pg_stat_activity: > > | backend_start | xact_start | > query_start | state_change | > wait_event_type | wait_event | state | backend_xid | backend_xmin | > query > -------+--------------+-----+----------+----------+------------------+-------------+-----------------+-------------+-------------------------------+-------------------------------+-------------------------------+------------------------------ > | 2019-09-23 20:29:45.127527+00 | 2019-09-23 20:29:45.12886+00 | > 2019-09-23 20:29:45.12886+00 | 2019-09-23 20:29:45.128861+00 | > | | active | 808 | 808 | select > import_wss() > | 2019-09-23 20:30:01.624853+00 | 2019-09-23 20:30:58.047317+00 | > 2019-09-23 20:30:58.047317+00 | 2019-09-23 20:30:58.047318+00 | > | | active | | 808 | > autovacuum: ANALYZE wss.RowCoding > | 2019-09-23 20:31:01.644824+00 | 2019-09-23 20:31:01.666711+00 | > 2019-09-23 20:31:01.666711+00 | 2019-09-23 20:31:01.666712+00 | > | | active | | 808 | > autovacuum: ANALYZE wss.WSSData > | 2019-09-23 20:31:14.101808+00 | 2019-09-23 20:31:14.103306+00 | > 2019-09-23 20:31:14.103306+00 | 2019-09-23 20:31:14.103307+00 | > | | active | | 808 | select * > from pg_stat_activity > (4 rows) > > | backend_start | xact_start | > query_start | state_change | > wait_event_type | wait_event | state | backend_xid | backend_xmin | > query > -------+--------------+-----+----------+----------+------------------+-------------+-----------------+-------------+-------------------------------+-------------------------------+-------------------------------+------------------------------- > | 2019-09-23 20:29:45.127527+00 | 2019-09-23 20:29:45.12886+00 | > 2019-09-23 20:29:45.12886+00 | 2019-09-23 20:29:45.128861+00 | > | | active | 808 | 808 | select > import_wss() > | 2019-09-23 20:34:21.01283+00 | 2019-09-23 20:34:21.014473+00 | > 2019-09-23 20:34:21.014473+00 | 2019-09-23 20:34:21.014475+00 | > | | active | | 808 | select * > from pg_stat_activity > (2 rows) > > Can you create a self-contained test case that acts like this? > > > I can try to duplicate it if this doesn't provide the details needed. > > corey -- Adrian Klaver adrian.klaver@aklaver.com
On Mon, Sep 23, 2019 at 4:31 PM Adrian Klaver <adrian.klaver@aklaver.com> wrote:
Hmm, are there triggers on wss_entries that are UPDATEing/DELETEing
entries elsewhere?
No, that table is pretty much stand-alone. What we're seeing here is most likely caused by the initial copy of the legacy db tables.
This happens when creating the local test db which I do right before the tests. I can avoid the issue if I monitor top and wait for the analyze to complete on all the related tables.
corey
On 9/23/19 2:34 PM, Corey Taylor wrote: > On Mon, Sep 23, 2019 at 4:31 PM Adrian Klaver <adrian.klaver@aklaver.com > <mailto:adrian.klaver@aklaver.com>> wrote: > > Hmm, are there triggers on wss_entries that are UPDATEing/DELETEing > entries elsewhere? > > > No, that table is pretty much stand-alone. What we're seeing here is > most likely caused by the initial copy of the legacy db tables. > > This happens when creating the local test db which I do right before the > tests. I can avoid the issue if I monitor top and wait for the analyze > to complete on all the related tables. Big hammer approach: alter system set autovacuum = off; SELECT pg_reload_conf(); Do work alter system reset autovacuum; SELECT pg_reload_conf(); Smaller hammer: https://www.postgresql.org/docs/11/sql-createtable.html#SQL-CREATETABLE-STORAGE-PARAMETERS "autovacuum_enabled, toast.autovacuum_enabled (boolean)" which can be done by ALTER TABLE also: https://www.postgresql.org/docs/11/sql-altertable.html > > corey -- Adrian Klaver adrian.klaver@aklaver.com
On Mon, Sep 23, 2019 at 4:50 PM Adrian Klaver <adrian.klaver@aklaver.com> wrote:
Smaller hammer:
https://www.postgresql.org/docs/11/sql-createtable.html#SQL-CREATETABLE-STORAGE-PARAMETERS
"autovacuum_enabled, toast.autovacuum_enabled (boolean)"
which can be done by ALTER TABLE also:
https://www.postgresql.org/docs/11/sql-altertable.html
Thanks for the feedback. I think we'll be able to work around this issue in a way that is reliable enough to script.
I am curious if this is a "known" issue with restoring tables and analyze running at some point after while performing a select on the tables. It would be kind of nice to know when to predict this kind of situation.
corey
On 9/23/19 3:43 PM, Corey Taylor wrote: > On Mon, Sep 23, 2019 at 4:50 PM Adrian Klaver <adrian.klaver@aklaver.com > <mailto:adrian.klaver@aklaver.com>> wrote: > > Smaller hammer: > > https://www.postgresql.org/docs/11/sql-createtable.html#SQL-CREATETABLE-STORAGE-PARAMETERS > > "autovacuum_enabled, toast.autovacuum_enabled (boolean)" > > which can be done by ALTER TABLE also: > > https://www.postgresql.org/docs/11/sql-altertable.html > > > > Thanks for the feedback. I think we'll be able to work around this > issue in a way that is reliable enough to script. > > I am curious if this is a "known" issue with restoring tables and > analyze running at some point after while performing a select on the > tables. It would be kind of nice to know when to predict this kind of > situation. Usually what is seen here is the opposite, that tables are restored and ANALYZE is not run and performance on the subsequent queries is poor due to lack of current statistics. What is the restore process? > > corey -- Adrian Klaver adrian.klaver@aklaver.com
On Mon, Sep 23, 2019 at 5:51 PM Adrian Klaver <adrian.klaver@aklaver.com> wrote:
Usually what is seen here is the opposite, that tables are restored and
ANALYZE is not run and performance on the subsequent queries is poor due
to lack of current statistics.
What is the restore process?
For these specific legacy db tables, they are isolated in a separate schema. We then use pg_restore to restore the entire schema. Essentially just:
pg_restore -n wss --no-owner
corey
On 9/23/19 3:56 PM, Corey Taylor wrote: > On Mon, Sep 23, 2019 at 5:51 PM Adrian Klaver <adrian.klaver@aklaver.com > <mailto:adrian.klaver@aklaver.com>> wrote: > > Usually what is seen here is the opposite, that tables are restored and > ANALYZE is not run and performance on the subsequent queries is poor > due > to lack of current statistics. > > What is the restore process? > > > For these specific legacy db tables, they are isolated in a separate > schema. We then use pg_restore to restore the entire schema. > Essentially just: > > pg_restore -n wss --no-owner Per my previous post and below, the above does not kick off an ANALYZE: https://www.postgresql.org/docs/11/app-pgrestore.html "Once restored, it is wise to run ANALYZE on each restored table so the optimizer has useful statistics; see Section 24.1.3 and Section 24.1.6 for more information." So is there some other step in the process that occurs after the restore and before you run your function? > > corey -- Adrian Klaver adrian.klaver@aklaver.com
On Mon, Sep 23, 2019 at 7:23 PM Adrian Klaver <adrian.klaver@aklaver.com> wrote:
"Once restored, it is wise to run ANALYZE on each restored table so the
optimizer has useful statistics; see Section 24.1.3 and Section 24.1.6
for more information."
So is there some other step in the process that occurs after the restore
and before you run your function?
There are several other restore called and a delete query that clears out an unrelated table.
However, I think this solves the issue for us and the mystery. The ANALYZE was missing which reduces an unending query down to a minute. The ANALZYE runs very quickly on its own so we're simply going to fix the issue by following documented advice.
I guess the length of the query when before/during the ANALZYE felt like something more was wrong.
corey
On 9/23/19 5:28 PM, Corey Taylor wrote: > On Mon, Sep 23, 2019 at 7:23 PM Adrian Klaver <adrian.klaver@aklaver.com > <mailto:adrian.klaver@aklaver.com>> wrote: > > "Once restored, it is wise to run ANALYZE on each restored table so the > optimizer has useful statistics; see Section 24.1.3 and Section 24.1.6 > for more information." > > So is there some other step in the process that occurs after the > restore > and before you run your function? > > > There are several other restore called and a delete query that clears > out an unrelated table. > > However, I think this solves the issue for us and the mystery. The > ANALYZE was missing which reduces an unending query down to a minute. > The ANALZYE runs very quickly on its own so we're simply going to fix > the issue by following documented advice. Aah, so it was the common case. Order is restored to the Postgres Universe:) > > I guess the length of the query when before/during the ANALZYE felt like > something more was wrong. > > corey -- Adrian Klaver adrian.klaver@aklaver.com