Performance of MoreSQL

Charts the performance of MoreSQL lag on a Heroku dyno.

Latency From Mongo->Postgres As Measured by Postgres Trigger

Methodology

Setup postgres trigger that measures latency between updated_at field and NOW(). Then trigger many (28k) updates. Record the trigger payloads and plot using RMarkdown.

For this measurement, we setup a postgres trigger that fires when any record on given collection is updated. We then updated the 28k records in that collection.

Using a postgres trigger combined with object touch in mongo allows us to see millisecond precision, which is not possible using bson.MongoTimestamp data.

Trigger in Postgres

-- Trigger for pushing data onto notify channel
CREATE OR REPLACE FUNCTION notify_row_changes()
    RETURNS trigger AS $$
DECLARE
    current_row RECORD;
    old_row json;
    new_row json;
BEGIN
    IF TG_OP IN ('INSERT', 'UPDATE') THEN
        current_row := NEW;
        new_row := row_to_json(NEW);
    ELSE
        current_row := OLD;
        new_row := '{}'::json;
    END IF;
    IF TG_OP = 'INSERT' THEN
        old_row := '{}'::json;
    ELSEIF TG_OP IN ('UPDATE', 'DELETE') THEN
        old_row := row_to_json(OLD);
    END IF;
    PERFORM pg_notify(
        'row_changes',
        json_build_object(
            'timestamp', NOW(),
            'uuid', uuid_generate_v4(),
            'table', TG_TABLE_NAME,
            'action', TG_OP,
            '_id', current_row._id,
            'updated_at', current_row.updated_at,
            'ms_lag', extract(MILLISECONDS from INTERVAL '08:00' + NOW() - current_row.updated_at)
        )::text
    );
    RETURN current_row;
END;
$$ LANGUAGE plpgsql;

CREATE TRIGGER changes_to_row_trigger BEFORE insert or update or delete ON sample_items
FOR EACH ROW EXECUTE PROCEDURE notify_row_changes();

ms_lag was calculated as follows:

extract(MILLISECONDS from INTERVAL '08:00' + NOW() - updated_at) as ms_lag

The trigger output

NOTIFY’s output was observed using Postgres’s LISTEN functionality and a payload was delivered in the following schema:

{
  "timestamp": "2017-02-24T00:08:20.91831+00:00",
  "uuid": "e25ec752-7de3-4de0-b764-bdac9af1a05b",
  "table": "sample_items",
  "action": "INSERT",
  "_id": "4f60c45452e7520003000018",
  "updated_at": "2017-02-24T00:08:20.371",
  "ms_lag": 547.31
}

Results

df <- build_df("ms_lag_from_28000_entries_calculated_by_trigger.log")
print_quantile(df)

[1] "Mean latency: 585.585214235771"
[1] "Quantile by % Chance Latency will be <= this duration (ms)"
      25%       50%       75%       90%       95%       98%       99%      100% 
 383.3840  529.2315  713.8370 1063.5870 1194.5130 1288.7950 1330.8820 1476.4480 

print_histogram(df, "Histogram of ms_lag vs count", "ms_lag", "count")

Conclusion

Looking at the Quantile percentages when testing out MoreSQL, 50% of requests come through with 529ms or less of lag. 90% of requests were processed in trigger with 1063ms of lag or less. 100% of requests came through in 1500ms of lag or less.