More thoroughly clean up current admin privileges table.

[mtbc]

Uses metadata introduced in PostgreSQL 9.4 to more aggressively trim the _current_admin_privileges table. It must include the rows pertaining to the currently active transactions but, otherwise, the smaller the table, the faster the checks.

[joshmoore]

TIL!

[joshmoore]

How often is this called and what's a typical under-load size for the table? Just trying to figure out if the 10x difference in these calls is worth it:

omero=# explain analyze select txid_snapshot_xmin(txid_current_snapshot());
                                     QUERY PLAN
------------------------------------------------------------------------------------
 Result  (cost=0.00..0.01 rows=1 width=8) (actual time=0.005..0.005 rows=1 loops=1)
 Planning time: 0.014 ms
 Execution time: 0.015 ms
(3 rows)

omero=# explain analyze SELECT DISTINCT backend_xid FROM pg_stat_activity;
                                                                    QUERY PLAN

---------------------------------------------------------------------------------------------------------------------------------------
------------
 HashAggregate  (cost=2.91..2.92 rows=1 width=4) (actual time=0.101..0.101 rows=1 loops=1)
   Group Key: s.backend_xid
   ->  Nested Loop  (cost=1.17..2.91 rows=1 width=4) (actual time=0.082..0.096 rows=10 loops=1)
         ->  Hash Join  (cost=1.05..2.44 rows=2 width=8) (actual time=0.073..0.076 rows=10 loops=1)
               Hash Cond: (s.datid = d.oid)
               ->  Function Scan on pg_stat_get_activity s  (cost=0.00..1.00 rows=100 width=12) (actual time=0.039..0.039 rows=10 loops
=1)
               ->  Hash  (cost=1.02..1.02 rows=2 width=4) (actual time=0.011..0.011 rows=5 loops=1)
                     Buckets: 1024  Batches: 1  Memory Usage: 9kB
                     ->  Seq Scan on pg_database d  (cost=0.00..1.02 rows=2 width=4) (actual time=0.006..0.008 rows=5 loops=1)
         ->  Index Only Scan using pg_authid_oid_index on pg_authid u  (cost=0.13..0.22 rows=1 width=4) (actual time=0.001..0.001 rows=
1 loops=10)
               Index Cond: (oid = s.usesysid)
               Heap Fetches: 10
 Planning time: 0.172 ms
 Execution time: 0.143 ms
(14 rows)

What kind of speed ups did you see?

[mtbc]

I'm afraid I no longer remember, we were allowing PostgreSQL 9.3 back when I was looking into this! Normally the table's fairly empty as there aren't normally many transactions by admins in progress; it's cleaned up every ten seconds I think, something like that, so in the typical case nobody should notice any difference.

This PR protects against a pathological case: a long-running transaction at a time when admins are up to stuff. A high fraction of the rows on this table might refer to completed transactions but if they started after that long-running transaction then they'll simply accumulate until it completes.

[joshmoore]

👍

Makes sense. Only running in the background, I can't imagine it will have much of an impact either:

public class LightAdminPrivilegesCleanup implements Runnable {
...
    /**
     * Start a new scheduled repeating task for cleaning up the <tt>_current_admin_privileges</tt> database table.
...
     * @param delay the interval to wait in between cleanups, in seconds
     */
    public LightAdminPrivilegesCleanup(SqlAction sqlAction, int delay) {
...
        /* require delay of at least half the interval */
        halfDelayMs = 500L * delay;
    }

    @Override
    public void run() {
        if (latestRunEnded + halfDelayMs < System.currentTimeMillis()) {
            LOGGER.debug("running periodic cleanup of _current_admin_privileges table");
        } else {
            /* simple emulation of ThreadPoolTaskScheduler.scheduleWithFixedDelay */
            LOGGER.debug("skipping periodic cleanup of _current_admin_privileges table");
            return;
        }
        sqlAction.deleteOldAdminPrivileges(transactionIds);
        transactionIds = sqlAction.findOldAdminPrivileges();
        latestRunEnded = System.currentTimeMillis();
    }

[joshmoore]

Just found this on merge-ci:

root@03c47d4df030:/# psql --version
psql (PostgreSQL) 10.7 (Debian 10.7-1.pgdg90+1)

Caused by: org.springframework.jdbc.BadSqlGrammarException: StatementCallback; bad SQL grammar [SELECT DISTINCT transaction FROM _curre
nt_admin_privileges WHERE transaction NOT IN (SELECT DISTINCT backend_xid FROM pg_stat_activity)]; nested exception is org.postgresql.u
til.PSQLException: ERROR: operator does not exist: bigint = xid
  Hint: No operator matches the given name and argument type(s). You might need to add explicit type casts.
  Position: 78
        at org.springframework.jdbc.support.SQLStateSQLExceptionTranslator.doTranslate(SQLStateSQLExceptionTranslator.java:99) ~[spring
-jdbc.jar:4.3.14.RELEASE]
        at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.jav
a:73) ~[spring-jdbc.jar:4.3.14.RELEASE]
        at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.jav
a:82) ~[spring-jdbc.jar:4.3.14.RELEASE]
        at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.jav
a:82) ~[spring-jdbc.jar:4.3.14.RELEASE]
        at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:419) ~[spring-jdbc.jar:4.3.14.RELEASE]
        at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:478) ~[spring-jdbc.jar:4.3.14.RELEASE]
        at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:488) ~[spring-jdbc.jar:4.3.14.RELEASE]
        at ome.util.SqlAction$Impl.findOldAdminPrivileges(SqlAction.java:739) ~[omero-model.jar:5.6.2-SNAPSHOT]
        at sun.reflect.GeneratedMethodAccessor2302.invoke(Unknown Source) ~[na:na]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_192]
        at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_192]
        at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:333) ~[spring-aop.jar:4.3.14.RELEASE]
        at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:190) ~[spring-a
op.jar:4.3.14.RELEASE]
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157) ~[spring-aop.jar:4
.3.14.RELEASE]
        at ome.util.SqlAction$LoggingSqlAction.invoke(SqlAction.java:85) ~[omero-model.jar:5.6.2-SNAPSHOT]
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) ~[spring-aop.jar:4.3.14.RELEASE]
        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:213) ~[spring-aop.jar:4.3.14.RELEASE]
        at com.sun.proxy.$Proxy6.findOldAdminPrivileges(Unknown Source) ~[na:na]
        at ome.security.basic.LightAdminPrivilegesCleanup.run(LightAdminPrivilegesCleanup.java:68) ~[omero-server.jar:5.6.1-SNAPSHOT]
        at sun.reflect.GeneratedMethodAccessor2300.invoke(Unknown Source) ~[na:na]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_192]
        at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_192]
        at org.springframework.util.MethodInvoker.invoke(MethodInvoker.java:265) ~[spring-core.jar:4.3.22.RELEASE]
        at org.springframework.scheduling.quartz.MethodInvokingJobDetailFactoryBean$MethodInvokingJob.executeInternal(MethodInvokingJobDetailFactoryBean.java:257) ~[spring-context-support.jar:4.3.22.RELEASE]
        ... 5 common frames omitted

cc: @mtbc

[mtbc]

Thank you, I should look into that!