Adestra Technical Solutions: Alerts - Long Running Jobs
Environment
Adestra
Symptoms
Long Running Jobs
Resolution Summary
Cleared long running job.
Details
At any given time the Adestra Technical Solutions Alerts channel can ping with a long-running job. It is It is the responsibility of Technical Solutions to look into any slow or long running jobs to see why they have been running for long periods of time and what we can do to help speed them up.
We need to look into these because long running jobs may be having an effect on other clients and can cause delays in any similar jobs they have running.
We are made aware of long running jobs in a couple of ways, these are:
- Via the technical solutions Teams channel from one of the development or system team members
- Via a Nagios alert in the 'Technical Solutions - Alerts' Teams channel
- Via a Support ticket
Here are some examples of long running jobs that we may encounter:
- Dynamic List Updates
- Exports
- Filters
- Add To List Actions Automations
Create a ticket for the alert
Before starting to look into the alert/long running job, a TS jira ticket needs to be created to represent the work and the issue.
The ticket needs to be created in the TS Jira project.
Below is an example of a previous alert ticket.
https://uplandsoftware.atlassian.net/browse/TS-12357
Subject line - Alerts - <account name> - <query snippet>
Example: Alerts - Email Bureau - DELETE FROM lookup
Labels - Alert
Sprint - Current active TS sprint
Priority - High
Informing Support
In the case where a job has been killed and the client needs to be informed, Support will need to be made aware of the details and will take charge of comms with the client. For TS, all that is required is for the details to be sent to Support via email informing them the job has been killed, any relevant details and asking for Support to reach out to the client to make them aware the job run failed. In some scenarios it may be appropriate to offer the manual rerunning of the job/function that failed, for example, an export. Support can then re-raise a new Support ticket following their conversation with the client should this be required.
adestra-support@uplandsoftware.com
Investigating the Alert
Use the below query to find what is running for the account. The database name needs to be inserted.
SELECT
datid,
datname,
pid,
xact_start
FROM pg_stat_activity
WHERE datname = 'amf_database_name'
ORDER BY xact_start
Once you have the information using the above query, you will want to look at the timestamp of the xact_start value and match that to the alert pinging in the teams channel.
For example the timestamp here is '2023-07-06 02:44:17' - this needs to be the same timestamp as the running job when running the
Likewise, you can view the current running jobs via the UI. This can be found via the management > jobs > running and filtering by the account. Again, the timestams here for the time the jobs started to run will match with the timestamp from the query ran above.
Help, I can't find the pid!?
Sometimes there will be instances where jobs are running via the management > jobs area but cannot be found by running the above query against the pg_stat_activity table.
To find the pid for these kinds of jobs you can follow the below steps.
Find the server_pid
In Adestra navigate to management > jobs and select the job needed to find the pid for.
When in the specific job at the bottom there is reference to the server_pid
For this job the server pid is 90856.
Also make not of the job server the job is running on.
Get the client_port
Now log onto the relevant job server which was found from the above.
Using the server pid again, as above, run the below command. This will output what is running against the server pid.
ps auxwww | grep <server_pid)
This will look something like the below. Please note, the example below is using a different server_pid than the one demonstrated above.
[10:54][beckie.powell@job-42:~]$ ps auxwww | grep 76735
cmi 13812 0.0 0.5 505544 286852 - Ss Tue07AM 1:49.98 AMF job worker busy q:import_transaction child:76735 (perl5.14.4)
cmi 76735 0.0 0.5 515796 293412 - S 2:56PM 1:26.50 AMF job import_transaction A:682 I:580606 0/100 (0%) (perl5.14.4)
beckie.powell 48027 0.0 0.0 360 280 2 R+ 10:55AM 0:00.00 grep --color 76735
We can see the below is running for server_pid 76735
cmi 76735 0.0 0.5 515796 293412 - S 2:56PM 1:26.50 AMF job import_transaction A:682 I:580606 0/100 (0%) (perl5.14.4)
In this example it's a import transaction.
Now the check has been done to confirm the job running for the server_pid, the below can be ran to find the client_port
sockstat | grep <client_pid)
Below is an example of that output:
[10:55][beckie.powell@job-42:~]$ sockstat | grep 76735
cmi perl5.14.4 76735 4 tcp4 10.154.131.42:22695 10.154.129.92:5432
cmi perl5.14.4 76735 6 tcp4 10.154.131.42:25760 10.154.131.173:6379
cmi perl5.14.4 76735 7 tcp4 10.154.131.42:28733 10.154.131.173:6379
cmi perl5.14.4 76735 8 tcp4 10.154.131.42:28745 10.154.129.92:5432
cmi perl5.14.4 76735 11 tcp4 10.154.131.42:28759 10.154.129.77:5432
These are all the servers it's connected to with what port. Port 5432 is postgres, so those are pg connections.
Out of these, 10.154.129.77 is db-46a, so that's likely the account db connection
cmi perl5.14.4 76735 11 tcp4 10.154.131.42:28759 10.154.129.77:5432
The part needed from this is the client_port which in this example is 28759.
Lookup the pid using the client_port
Now the client_port has been grabbed this can be used to finally find the pid. This will be done in the account DB using the below query.
SELECT
datid,
datname,
pid,
xact_start,
query
FROM pg_stat_activity
WHERE datname = 'amf_informa_plc'
AND client_port = <client_port>
ORDER BY xact_start
Below is an example output.
-[ RECORD 1 ]-------------------------------------------------------------------------------------------
datid | 30541399
datname | amf_informa_plc
pid | 14406
xact_start | 2024-06-27 11:19:34.380752+01
query | UPDATE "baskets" SET "contact_id" = $1, "email" = $2, "updated" = NOW() WHERE ( "id" = $3 )
This gives the pid as we know and which can then be used as required.
Once you are confident you have found the job you want to kill (the timestamps match with the alert and the current running jobs) you will then need to kill or stop the job from running. To do this, you need the PID value taken from the above query.
You will then need to run the below query (inserting the relevant PID) value in the account DB. This will stop the job from running.
SELECT
pg_cancel_backend(<<PID>>)
pg_cancel_backend
-------------------
t
(1 row)
For cancel a whole session as opposwed to just a query (which is what the above does) then use the below. CAUTION: The below should only be used when appropriate. The above should fulfill requirements for most instances. The below stops subsequent queries so it can prevent cleanup processes from running and cause adverse complications
SELECT
pg_terminate_backend(<<PID>>)
Long Running RTBF (contact deletion)
Sometimes RTBF requests (contact deletion) can take a while to run/complete. The below query can be used to identify whether there are any current RTBF jobs running in the DB. This needs running in the system DB.
SELECT
*
FROM job.rtbf
WHERE account_id = 1234
AND date_completed IS NULL
Long Running Filters
You may see cases about dynamic lists taking a long time to update or filters running against a list for a long period of time. If these come up, in the database, we can run a few checks on the filter SQL to identify which part of the filter is slow and if amending the autovac setting would help. Here is what you need to do:
- Connect to their account on tech-41:
acc <<account name>> - Find the SQL for the filter in question:
SELECT
*
FROM filters
WHERE id = ?NOTE: Instead of inserting a '?' in your query, enter the filter ID
- Then run a EXPLAIN ANALYZE on the SQL:
EXPLAIN ANALYZE <<enter filter SQL here>> - Analyse the cost and vacuum:
- Once that has come back, view the 'cost' for each of the nodes to see which are taking longer than others to run. Once you have identified the node or nodes that are slowing down the filter run time, you can then run a VACUUM ANALYZE on the table linked.
VACUUM ANALYZE <<insert table name>>
- Once that has come back, view the 'cost' for each of the nodes to see which are taking longer than others to run. Once you have identified the node or nodes that are slowing down the filter run time, you can then run a VACUUM ANALYZE on the table linked.
- Re-analyse the cost:
- Once your vacuum has completed, you will then need to rerun your EXPLAIN ANALYZE to see if it has reduced the cost for these nodes. If so this means tweaking the autovac on the desired table may help with speeding up filter run times.
Here are some example cases of where this has been needed:- More2 - 00365882
- Long Tall Sally - 00364107
- Once your vacuum has completed, you will then need to rerun your EXPLAIN ANALYZE to see if it has reduced the cost for these nodes. If so this means tweaking the autovac on the desired table may help with speeding up filter run times.
Long Running Exports
If you have been notified of any long running exports by one of the dev team or by a Nagios alert, you will need to run some checks to identify which export is flagging these alerts.
- Firstly, you will need to check what is currently running for that account:
SELECT
*
FROM pg_stat_activity
WHERE datname = '<<database name>>' - Find the job:
- In the jobs tab, there is a 'start time' column which will show you when the export started. As well as this, there is also a 'server host' column which which show you which server the query is running on (i.e app-1, app-2, app-3 or app-4).
- Locate the export:
- Once you have identified the slow running export for the account via the jobs tab, you can then use the schedule id which is shown in the 'args' column to locate the export in the clients account.
- To find the export linked to the schedule id, you can search the export.schedule table using the schedule id. Alternatively, you can to go to the 'admin' tab of the account and then to the 'schedules tab'. In the schedules tab, you should then see another sub tab called 'exports' and the id column will be the schedule id.
- Analyse the export: → Not so much needed anymore due to the fix we have in place, but might be worth a look sometimes
- When you have identified the slow export, you will then be able to see what it does to see if we can make any recommendations to the client to help this run faster.
- Kill the export:
- If the export is causing problems, we will then need to kill it. To do this you will need to grab the PID from the SELECT statement that was run in point 1. This is the number within the square brackets.
- Once you have this PID you would need to run the below:
SELECT pg_cancel_backend(<<PID>>)
This should return a 't' to confirm that the export has then been cancelled. If this is not an on-going long running export, make sure you alert the second line team so they can contact the client.
Adding an index
We've now developed a new and incredibly effective way of resolving long running export issues. We now apply a brin index to the timestamp column, like so:
CREATE INDEX CONCURRENTLY eventlog_timestamp_idx ON eventlog USING brin (timestamp)
Due to exports using this column to determine what data it needs to grab, this index has had incredible results in greatly reducing export times. I think I've gotten exports down from ~24 hours to minutes!
Once you've killed the export, have a look at the eventlog table like so:
amf_assurant=# \d eventlog Table "public.eventlog" Column | Type | Modifiers------------+-----------------------------+------------------------------------------------------- id | bigint | not null default nextval('eventlog_id_seq'::regclass) event_id | integer | contact_id | integer | not null timestamp | timestamp without time zone | not null default now() object_id | integer | launch_id | integer |Indexes: "eventlog_pkey" PRIMARY KEY, btree (id) "eventlog_contact_id_idx" btree (contact_id) "eventlog_event_id_idx" btree (event_id) "eventlog_launch_id_idx" btree (launch_id) CLUSTERTriggers: eventlog_activity_trigger BEFORE INSERT ON eventlog FOR EACH ROW EXECUTE PROCEDURE stats.activity_trigger() eventlog_delete_trig AFTER DELETE ON eventlog FOR EACH ROW EXECUTE PROCEDURE log.eventlog_deletion_trig()As you can see there are no indexes against this timestamp field. You can go ahead and create a ticket like below, post in the PR and Tickets channel and wait for it to be QA approved:
https://uplandsoftware.atlassian.net/browse/TS-10121 - Can't find link
Once it has been approved you can go ahead and action the query:
amf_assurant=# CREATE INDEX CONCURRENTLY eventlog_timestamp_idx ON eventlog USING brin (timestamp);CREATE INDEXamf_assurant=#You cannot run it in a transaction as it's being created concurrently. Once it has finished though you should have your index applied:
Table "public.eventlog"
Column | Type | Modifiers
------------+-----------------------------+-------------------------------------------------------
id | bigint | not null default nextval('eventlog_id_seq'::regclass)
event_id | integer |
contact_id | integer | not null
timestamp | timestamp without time zone | not null default now()
object_id | integer |
launch_id | integer |
Indexes:
"eventlog_pkey" PRIMARY KEY, btree (id)
"eventlog_contact_id_idx" btree (contact_id)
"eventlog_event_id_idx" btree (event_id)
"eventlog_launch_id_idx" btree (launch_id) CLUSTER
"eventlog_timestamp_idx" brin ("timestamp")
Triggers:
eventlog_activity_trigger BEFORE INSERT ON eventlog FOR EACH ROW EXECUTE PROCEDURE stats.activity_trigger()
eventlog_delete_trig AFTER DELETE ON eventlog FOR EACH ROW EXECUTE PROCEDURE log.eventlog_deletion_trig()
You will then need to re-run the export you just killed, which you can do by following this guide:
Rerunning Failed Exports in Bulk
-- This is now fairly outdated for exports as the index method works much better, but might still be useful for the lookup table (lists) -->
Checking The Database
If you find that you need to tweak the settings on the eventlog or the lookup table, you will need to run some further SELECT statements to see what tweaks need to be made as you do not want to be too aggressive as this can cause the database to lock.
NOTE: Make sure you place all of the below information and the outcomes of these searches into your changeset ticket as the team will need to review these to make sure your autovac update will do what is intended.
- Check the statistics, this is what the system believes is the count of the table:
SELECT
reltuples::int AS count
FROM pg_class
WHERE relname = '<<table>>' - Find the actual count of the table:
SELECT
COUNT(*)
FROM <<table>> - See when the autoanalyze last ran and make note of the date:
Eventlog:
SELECT
relname,
last_vacuum,
last_analyze,
last_autoanalyze
FROM pg_stat_user_tables
WHERE last_autoanalyze IS NOT NULL
AND relname = 'eventlog'
ORDER BY 3
DESC LIMIT 10
Lookup:
SELECT
relname,
last_vacuum,
last_analyze,
last_autoanalyze
FROM pg_stat_user_tables
WHERE last_autoanalyze IS NOT NULL
AND relname = 'lookup'
ORDER BY 3
DESC LIMIT 10 - Then you will need to work out how many rows change per hour:
Eventlog:
SELECT
date_trunc('hour',timestamp),
COUNT(*)
FROM eventlog
WHERE timestamp::date = '<<yyyy-mm-dd>>'::date
GROUP BY 1
ORDER BY 1
Lookup:
This is the check you would do for list history:
SELECT
date_trunc('hour',log.activity.timestamp),
COUNT(*)
FROM log.lookup
LEFT JOIN log.activity
ON log.lookup.activity_id = log.activity.id
WHERE date_trunc('day',log.activity.timestamp) = date_trunc('day', now() -interval '1 day')
GROUP BY 1
ORDER BY 1
This is the check you would do for imports:
SELECT
date_trunc('hour',import_date),
SUM(count_imported)
FROM imports
WHERE import_date::date = '<<yyyy-mm-dd>>'::date
GROUP BY 1
ORDER BY 1 - Once you have gathered the above information, you will then need to do some further calculations to see how you should tweak the autovac settings on your desired table.
- Using the information from point 4, you will then be able to find counts which are higher than normal.
For example, on the below table, you can see that normally the count is in the hundreds, however there are spikes of it going above 50,000:
date_trunc | count
---------------------+--------
2018-01-12 00:00:00 | 114
2018-01-12 01:00:00 | 28
2018-01-12 02:00:00 | 10
2018-01-12 03:00:00 | 14
2018-01-12 04:00:00 | 160
2018-01-12 05:00:00 | 2
2018-01-12 06:00:00 | 5
2018-01-12 07:00:00 | 19
2018-01-12 08:00:00 | 43
2018-01-12 09:00:00 | 87391
2018-01-12 10:00:00 | 828
2018-01-12 11:00:00 | 106
2018-01-12 12:00:00 | 173
2018-01-12 13:00:00 | 108
2018-01-12 14:00:00 | 343
2018-01-12 15:00:00 | 104
2018-01-12 16:00:00 | 4935
2018-01-12 17:00:00 | 320683
2018-01-12 18:00:00 | 65
2018-01-12 19:00:00 | 50
2018-01-12 20:00:00 | 41
2018-01-12 21:00:00 | 78
2018-01-12 22:00:00 | 462
2018-01-12 23:00:00 | 41
(24 rows)
- Using the information from point 4, you will then be able to find counts which are higher than normal.
- From this you can grab a rounded number that relates to these peaks and divide this by the actual list count to grab the percentage for what you should tweak by. In the example above, the first peak is in the tens of thousands, here we picked the count 50,000 as we want the tweak to take affect for any changes that are 50,000 or above.
- To check the current settings you can run:
SELECT
relname,
reloptions
FROM pg_class
WHERE relname = <<table name>>
- To check the current settings you can run:
- Once you have decided the count you want to go by, you then need to divide this number by the actual row count, this will give you the percentage for your tweak:
ALTER TABLE eventlog SET (autovacuum_analyze_scale_factor = <<percentage>>)
- Once you have decided the count you want to go by, you then need to divide this number by the actual row count, this will give you the percentage for your tweak:
- Once your changeset ticket has been approved, you just need to run the 'ALTER TABLE' statement on the clients database.
Resolution Category
Problem/Incident::Product::Configuration
Keywords Long Running Jobs alerts nagios cancel kill alert nagios contact deletion right to be forgotten rtbf pid server tech-41 job server raexternalrequest
Upland RightAnswers Solution Manager - Version 2024R2