Keith's Ramblings…

Archive for the ‘logging’ tag

PG Jobmon Exception Handling

without comments

As a quick review for those unfamiliar with what PG Jobmon is, it’s an extension to allow autonomously logging steps within a function so that if the function fails, the individually logged steps are not rolled back and lost. This provides an audit trail and monitoring capabilities for functions critical to your database infrastructure. See my Projects page for the code and other posts tagged with “pg_jobmon” for more info.

One of the tricker issues I came across when making an extension out of the existing code that PG Jobmon was based on was getting useful errors back, both on the console and in the log tables. If an error happened before you logged the first step, or job logging even started, trying to handle  logging the errors in the exception block would cause some rather useless feedback, often hiding the real error. The below has become sort of a template for any function’s exception block where I use jobmon.

        IF v_job_id IS NULL THEN
            v_job_id := jobmon.add_job('JOB NAME HERE');
            v_step_id := jobmon.add_step(v_job_id, 'Exception occurred before job logging started');
        ELSIF v_step_id IS NULL THEN
            v_step_id := jobmon.add_step(v_job_id, 'EXCEPTION before first step logged');
        END IF;
        PERFORM jobmon.update_step(v_step_id, 'CRITICAL', 'ERROR: '||coalesce(SQLERRM,'unknown'));
        PERFORM jobmon.fail_job(v_job_id);
            CONTEXT: %', SQLERRM, v_ex_context;

This accounts for when an error occurs before job logging started (call to add_job) or if it occurs between job logging starting and the first step being logged (between add_job and first call to add_step). Another call to RAISE EXCEPTION with the original SQL error is made after all that to ensure the real error is still reported back normally.

UPDATE (2013-02-07): I’ve added some additional error output to the actual raising of the exception to better show where the error is coming from. If you’d like that in your jobmon log as well, just add the variable into the update_step() call. The only downside to this is that GET STACKED DIAGNOSTIC only works on 9.2.

Written by Keith

January 11th, 2013 at 11:46 am

PG Jobmon Reaches 1.0.0

without comments

We’ve been running PG Jobmon in our production databases at OmniTI for a while now and it’s been working very well. Found an issue with the monitoring function, polished some other features up and figured it was finally time to give it 1.0.0 stable once that was all fixed.

Since my last post, I did get the simple job logging functions added that I mentioned (back in 0.4.0). To just simply log the number of rows affected by a single query call, you can use sql_step(job_id, action, sql). It returns a boolean to let you be able to test whether the step was successful or not.

v_step_status := jobmon.sql_step(v_job_id, 'Test step 2', 'UPDATE test SET col2 = ''changed''');

The result in the job_detail table then looks like

job_id       | 1
step_id      | 2
action       | Test step 2
start_time   | 2012-12-28 22:32:32.750609-05
end_time     | 2012-12-28 22:32:32.768827-05
elapsed_time | 0.018218
status       | OK
message      | Rows affected: 2

If you just want to log a single query as a complete job, you can use sql_job(job_name, sql).

SELECT jobmon.sql_job('Test Query', 'UPDATE test SET changed_column = CURRENT_TIMESTAMP');

The result is similar to the simple step function, but makes an entire job log with the given name and a single step entry with how many rows were affected.

The other big change that came with 1.0.0 is with the check_job_status() monitoring function. It now no longer requires an interval argument, and it’s recommended not to pass one unless you really need to. The thing that brought this change about was if you passed an interval smaller than the highest threshold value set in the job_check_config table, it could return some confusing results. I could’ve made it return a clearer result, but honestly it really makes no sense at all to pass a smaller interval than what you’ve set to be monitored for in the configuration table. So now it throws an error if you do so. And if you just use the version that takes no argument, it automatically gets the largest interval threshold you’ve configured and uses that. So if you get a new longer job to monitor in the future, you no longer have to update your monitoring processes to account for it as long as you use the no-argument version.

The processes of monitoring for job problems has also been modified to allow check_job_status() to be able to raise notices when a job produces three level 2 (WARNING) alerts in a row as well. Previously this only happened with critical failures. The fail_job() function can now take an optional alert level argument to allow this to happen. This is useful for non-critical issues that, for example, shouldn’t cause a page to your oncall, but should still be looked into. For an example, see the next version of my Mimeo extension (>=0.9.0) that can send you a notification when a single replication batch has hit the configured row limit and may possibly cause replication to fall behind if it continues for too long. It’s an easily fixed problem and shouldn’t cause anyone to have to wake up in the middle of the night.

I’ve been using this extension extensively with several other extensions I’ve been working on that really need a good monitoring process available to make sure they are working properly. The first, mentioned above, is called Mimeo, which does specialized, per-table replication between PostgreSQL databases. The other is PG Partman, a table partition manager for time & serial based partitioning. Both of these processes would be pretty useless without some way to easily let you know they are working right and provide an audit trail when something goes wrong and you’re not around. The autonomous step logging that PG Jobmon provides, without rolling back all the logged steps when something goes wrong, does this wonderfully. Yes that kind of monitoring could be built right into those extensions, but I’ve always liked the part of the Unix philosophy of doing one thing and doing it well and allowing those smaller powerful tools to work together to a greater affect. And we’ve found that having PG Jobmon available for any other functions we want to monitor very helpful since it’s not tied directly into the other extensions.

PG Jobmon –
Mimeo –
PG Partman –

Written by Keith

December 31st, 2012 at 11:05 am

PostgreSQL Job Logging & Monitor Extension – The Logger

with one comment

Update 2012/06/05: So of course after I go publishing this blog post, I discover a major shortcoming in 0.3.0. It requires super-user privileges to actually run. Teach me to test with only my own account in the database. I’ll be pushing 0.3.1 out shortly with a fix to allow non-superusers to be able to use these logging functions. Just requires a little bit of configuration, which I’ve added to that section below and the file.

Job logging and monitoring in PostgreSQL can be an invaluable tool for tracking down issues when important database tasks are automated. OmniTI has some great job logging systems in place for the databases we support, but there was no consistent monitoring of this logging that was specifically built with it in mind. I thought this would be a great opportunity to take advantage of PostgreSQL 9.1’s new extensions capability to try and bring a consistent logging and monitoring tool into use that would be easily maintained and updatable. This blog post will first concentrate on the logging portion. I’ll do a follow up post about the monitor hopefully next month.

The first, and easier piece to pull into an extension format was the logging. Easier mostly because previous developers here had done a good job of getting logging working. 🙂 Since Postgres’s functions aren’t autonomous, true job logging can be difficult. If a function fails to run, everything that it was doing, including inserts to a logging table, would be rolled back. Using dblink to have Postgres connect back to itself is a neat trick to get autonomous functions working and have intermittent commits actually be persistent despite a job failure. The details of doing this aren’t really the main point of this blog post, though, so if you’d like to see the details on how this works, the source code of the extension is freely available.


First off, the new extension system makes the install (and future updates) a breeze. I set the extension up to be compatible with the PostgreSQL Extension Network so you can use make/make install to get the files in the correct location. It is available on pgxn, but it is marked testing, so it won’t show up in searches yet. Would like to get some feedback from others before making it v1.0 stable – (Update: version 1.0 (and greater) have been available for quite some time in both github & pgxn) After that, it’s just a matter of using the new 9.1 extension management commands. I’d recommend creating a schema instead of installing it to public. I’m assuming the schema jobmon in all examples, but you can choose whichever one you want. Note that the schema cannot be changed after install without reinstalling the extension (it is not relocatable). This extension has table data as well, so re-installation can possibly result in the loss of configuration and logging data without taking precautions.


How to Log Steps

pg_jobmon has some pretty basic functions for doing job logging so getting it up and working isn’t very difficult at all. To start off, some variables to hold job and step ids will need to be defined for any function that requires logging

v_job_id   bigint;
v_step_id  bigint;

To start your job logging for a function call the add_job(text) function, storing the ID it generates to a variable. What you enter for JOB NAME will be used in the jobmon.job_log table as the job_name column. All values for the job name are automatically capitalized for consistency and to make searching a little more predictable as to what the values will be. I’ll be using a new, specialized replication extension I’m working on, mimeo, to show examples of how pg_jobmon is used. Specifically, the snap replication which does a full copy of a table from one postgresql instance to another.

 v_job_id := jobmon.add_job('REFRESH SNAP: KEITH.TEST_TABLE');

This creates an entry in the jobmon.job_log table. pg_jobmon has a set of “show” functions that can make reading the job logs easier. I’ll talk more about them at the end, but I’ll be using them in these examples as well.

flpg=# select * from jobmon.show_job('REFRESH SNAP: KEITH.TEST_TABLE');
-[ RECORD 1 ]--------------------------------------
job_id     | 13
owner      | keith
start_time | 2012-06-03 18:52:10.686897-04
end_time   | 
status     | 
pid        | 13805

From here on out, job logging is primarily done with two functions: add_step(bigint, text) and update_step(bigint, text, text). add_step() is used to start tracking the progress of each step of the function that you’d like to monitor. The first argument is the job_id generated from add_job(). The text should be a short description of the step. Note that this description stays constant and is not changed as part of the update. add_step() returns a step_id that should be stored.

v_step_id := jobmon.add_step(v_job_id,'Grabbing Mapping, Building SQL');

This creates the first step for our job and is logged to the jobmon.job_detail table under the given job_id.

testdb=# select * from jobmon.show_detail(13);
-[ RECORD 1 ]+--------------------------------------------
job_id       | 13
step_id      | 21
action       | Grabbing Mapping, Building SQL
start_time   | 2012-06-03 18:52:10.722388-04
end_time     | 
elapsed_time | 
status       | 
message      |

Later in the function, after this step should have been completed, we update that step with the current status using update_step(). The first argument is the step_id that is to be updated. The next argument is a simple status. in this case everything should be ok if it reached this point, so it’s set to ‘OK’. (You can set whatever status message you wish here. Would recommend being consistent with the config table mentioned later.) The final argument is a message that can give more details as to results of this step. This was a fairly simple step, so just saying ‘done’ is good enough. You can update a status or message several times for a single step if needed, showing the current progress of longer running steps.

PERFORM jobmon.update_step(v_step_id, 'OK','Done');

-[ RECORD 1 ]+--------------------------------------------
job_id       | 13
step_id      | 21
action       | Grabbing Mapping, Building SQL
start_time   | 2012-06-03 18:52:10.722388-04
end_time     | 2012-06-03 18:52:10.791287-04
elapsed_time | 0.068899
status       | OK
message      | Done

When you’re done with this step and want to move on to the next, just call the add_step() function again to create a new step ID.

v_step_id := jobmon.add_step(v_job_id,'Inserting records into local table');

For this step we’ll provide a little more information to the message log. I’ve added a GET DIAGNOSTICS call to the portion where the INSERT is done to get the row count of this snap job. This is added to the message log so we can make sure rows were actually copied into the snap table.

EXECUTE v_insert_sql; 
PERFORM jobmon.update_step(v_step_id, 'OK','Inserted '||v_rowcount||' records');
flpg=# select * from jobmon.show_detail(13);
-[ RECORD 1 ]+--------------------------------------------
job_id       | 13
step_id      | 21
action       | Grabbing Mapping, Building SQL
start_time   | 2012-06-03 18:52:10.722388-04
end_time     | 2012-06-03 18:52:10.791287-04
elapsed_time | 0.068899
status       | OK
message      | Done
-[ RECORD 2 ]+--------------------------------------------
job_id       | 13
step_id      | 22
action       | Truncate non-active snap table
start_time   | 2012-06-03 18:52:10.81354-04
end_time     | 2012-06-03 18:52:10.849397-04
elapsed_time | 0.035857
status       | OK
message      | Done
-[ RECORD 3 ]+--------------------------------------------
job_id       | 13
step_id      | 23
action       | Inserting records into local table
start_time   | 2012-06-03 18:52:10.886041-04
end_time     | 2012-06-03 18:52:10.923981-04
elapsed_time | 0.03794
status       | OK
message      | Inserted 57 records

Handling Errors

If your job has a serious problem and needs to fail out completely, you can use the jobmon.fail_job(bigint) function. Provide it the job_id and it will set the status in jobmon.job_log to ‘CRITICAL’. Before calling this function you should do a call to jobmon.update_step() to provide details as to why the failure happened to the log. Note that this function DOES NOT stop your function from running. It only provides the functionality to log the failure. Adding these steps into an EXCEPTION is the common method we use, but it can be done anywhere you need

        PERFORM jobmon.update_step(v_step_id, 'CRITICAL', 'snapshot failed (' || coalesce(SQLERRM, 'unknown error') || ')');
        PERFORM jobmon.fail_job(v_job_id);

Speaking of exceptions, unless you handle the QUERY_CANCELED exception by adding logging instructions to it, manually cancelling your normally logged function will leave the final results in the log table as unfinished. If you want to cancel logged functions and properly make note of it in the logs, use the jobmon.cancel_job(bigint) function. Just provide it the job_id of the currently running function and it will do the following:

  • cancel the currently running job using pg_cancel_backend() (pid is stored in job_log table)
  • update the last step to set the status to CRITICAL
  • set the last step message to Manually cancelled via call to jobmon.cancel_job()
  • call the fail_job() function to close out the job as CRITICAL


A database superuser can just use these logging functions right away after extension creation. Non-superusers will require a bit of configuration. First, create a role that you can grant the following permissions to:

grant usage on schema jobmon to rolename;
grant usage on schema dblink to rolename;
grant select, insert, update, delete on all tables in schema jobmon to rolename;
grant execute on all functions in schema jobmon to rolename;
grant all on all sequences in schema jobmon to rolename;

Set your pg_hba.conf file to allow this user to connect locally to the database then add the rolename and password to the dblink_mapping table. Note the password is stored in the clear, so just give this role the limited permissions it needs and nothing else and control access to this table.

One thing to note about the close_job, fail_job, and cancel_job functions is that they use another configuration table, job_status_text, to set statuses to either OK or CRITICAL (this extension was made for use with Nagios, hence these text values). If you’d like different default values for your jobs, just update the error_text column, keeping the following code meanings in mind.

 error_code | error_text 
          1 | OK
          2 | WARNING
          3 | CRITICAL

1 always means the job ran without issue. 2 can be used as an intermediary status (next blog post on monitoring will go into more detail on this). And 3 means a complete failure of the job.
Update 2012/07/17: Version 0.3.4 has changed the column names of this table to make things a little more consistent with the monitoring portion of the extension

I’ll get into more detail on this with my monitoring post, but thought I’d at least mention this here since it involves values inserted to the logging table. I haven’t thought of any use cases for further status codes and these functions won’t use any others you may add to the table. If anyone thinks of any others that they feel should be added and used, I’m open to suggestions.

Reading Logs

Lastly for logging, you’ve seen examples of the show functions throughout this post. I won’t get into too much more detail on each of them since they are fairly self explanatory once a few bits of info are known ahead of time. First, all job names passed as parameters are automatically capitalized to be consistent with add_job(), so you don’t have to. Next, most have a default limit on the number of rows returned and this can be changed by passing an optional integer parameter. Also, all the show functions are set to return full row sets, so you can query and filter them just like a regular table. Of course, you can always query the job_log and job_detail tables directly as well. These were just created to try and make some of the more common queries we were writing against them easier to do. See the docs for more info.

Upcoming Features

A coworker mentioned a handy job logging function could be one that actually accepts a query to run and simply logs the number of rows affected. To quote him

1. log start of step
2. execute given sql
3. get rowcount via diagnostics
4. log end of step with status and rowcount.
something like:
perform jobmon.sql_step( v_job_id, 'doing some magic', 'INSERT INTO table (a,b,c) SELECT 
                * FROM other_table' );

(Update: The above function has been added as well as an “sql_job” function that can log an entire, single step job with a single call)

This covers the logging portion of this extension. Functions similar to these have been in use with several of our clients for quite a while. These have only been changed to be incorporated into an extension or add some new capability. The monitoring tables and function are still fairly new and should be in working order. Their basic use is covered in the readme file, but as I said in the beginning, I will be doing another blog post to cover their use. Would really appreciate any feedback, good and bad, from anyone that starts using it.This is also my first venture into making an extension, so if anyone has any feedback in that area, it would be much appreciated.

Written by Keith

June 4th, 2012 at 4:11 pm