CTE query formatting and slow-query-logging

.aliases

@@ -71,7 +71,7 @@ alias podman-stop='systemctl --user disable --now podman.socket && systemctl --u
 alias podman-use='export DOCKER_HOST="unix:///run/user/$UID/podman/podman.sock"; export TESTCONTAINERS_RYUK_DISABLED=true'
 
 alias gw=gradleWrapper
-alias pg-sql-run='docker run --name hsadmin-ng-postgres -e POSTGRES_PASSWORD=password -p 5432:5432 -d postgres:15.5-bookworm'
+alias pg-sql-run='docker run --name hsadmin-ng-postgres -e POSTGRES_PASSWORD=password -v COPY etc/postgresql-log-slow-queries.conf:/etc/postgresql/postgresql.conf -p 5432:5432 -d postgres:15.5-bookworm'
 alias pg-sql-stop='docker stop hsadmin-ng-postgres'
 alias pg-sql-start='docker container start hsadmin-ng-postgres'
 alias pg-sql-remove='docker rm hsadmin-ng-postgres'

Dockerfile

@@ -0,0 +1,10 @@
+# build using:
+# docker build -t postgres-with-contrib:15.5-bookworm .
+
+FROM postgres:15.5-bookworm
+
+RUN apt-get update && \
+    apt-get install -y postgresql-contrib && \
+    apt-get clean
+
+COPY etc/postgresql-log-slow-queries.conf /etc/postgresql/postgresql.conf

doc/rbac-performance-analysis.md

@@ -0,0 +1,247 @@
+# RBAC Performance Analysis
+
+This describes the analysis of the legacy-data-import which took way too long, which turned out to be a problem in the RBAC-access-rights-check.
+
+
+## Our Performance-Problem
+
+During the legacy data import for hosting assets we noticed massive performance problems. The import of about 2200 hosting-assets (IP-numbers, managed-webspaces, managed- and cloud-servers) as well as the creation of booking-items and booking-projects as well as necessary office-data entities (persons, contacts, partners, debitors, relations) **took 10-25 minutes**.
+
+We could not find a pattern, why the import mostly took about 25 minutes, but sometimes took *just* 10 minutes. The impression that it had to do with too many other parallel processes, e.g. browser with BBB or IntelliJ IDEA was proved wrong, but stopping all unnecessary processes and performing the import again.
+
+
+## Preparation
+
+### Configuring PostgreSQL 
+
+The pg_stat_statements PostgreSQL-Extension can be used to measure how long queries take and how often they are called.
+
+The module auto_explain can be used to automatically run EXPLAIN on long-running queries.
+
+To use this extension and module, we extended the PostgreSQL-Docker-image:
+
+```Dockerfile
+FROM postgres:15.5-bookworm
+
+RUN apt-get update && \
+    apt-get install -y postgresql-contrib && \
+    apt-get clean
+
+COPY etc/postgresql-log-slow-queries.conf /etc/postgresql/postgresql.conf
+```
+
+And create an image from it:
+
+```sh
+docker build -t postgres-with-contrib:15.5-bookworm .
+```
+
+Then we created a config file for PostgreSQL in `etc/postgresql-log-slow-queries.conf`:
+
+```
+shared_preload_libraries = 'pg_stat_statements,auto_explain'
+log_min_duration_statement = 1000
+log_statement = 'all'
+log_duration = on
+pg_stat_statements.track = all
+auto_explain.log_min_duration = '1s'  # Logs queries taking longer than 1 second
+auto_explain.log_analyze = on         # Include actual run times
+auto_explain.log_buffers = on         # Include buffer usage statistics
+auto_explain.log_format = 'json'      # Format the log output in JSON
+listen_addresses = '*'
+```
+
+And a Docker-Compose config in 'docker-compose.yml':
+
+```
+version: '3.8'
+
+services:
+  postgres:
+    image: postgres-with-contrib:15.5-bookworm
+    container_name: custom-postgres
+    environment:
+      POSTGRES_PASSWORD: password
+    volumes:
+      - /home/mi/Projekte/Hostsharing/hsadmin-ng/etc/postgresql-log-slow-queries.conf:/etc/postgresql/postgresql.conf
+    ports:
+      - "5432:5432"
+    command:
+      - bash
+      - -c
+      - >
+        apt-get update &&
+        apt-get install -y postgresql-contrib &&
+        docker-entrypoint.sh postgres -c config_file=/etc/postgresql/postgresql.conf
+```
+
+### Activate the pg_stat_statements Extension
+
+The pg_stat_statements extension was activated in our Liquibase-scripts: 
+
+```
+create extension if not exists "pg_stat_statements";
+```
+
+### Running the Tweaked PostgreSQL
+
+Now we can run PostgreSQL with activated slow-query-logging:
+
+```shell
+docker-compose up -d
+```
+
+### Running the Import
+
+Using an environment like this:
+
+```shell
+export HSADMINNG_POSTGRES_JDBC_URL=jdbc:postgresql://localhost:5432/postgres
+export HSADMINNG_POSTGRES_ADMIN_USERNAME=postgres
+export HSADMINNG_POSTGRES_ADMIN_PASSWORD=password
+export HSADMINNG_POSTGRES_RESTRICTED_USERNAME=restricted
+export HSADMINNG_SUPERUSER=superuser-alex@hostsharing.net
+```
+
+We can now run the hosting-assets-import:
+
+```shell
+time gw-importHostingAssets
+```
+
+### Fetch the Query Statistics
+
+And afterward we can query the statistics in PostgreSQL:
+
+```SQL
+SELECT pg_stat_statements_reset();
+```
+
+
+## Analysis Result
+
+### RBAC-Access-Rights Detection query
+
+This CTE query was run over 4000 times during a single import and takes in total the whole execution time of the import process:
+
+```SQL
+WITH RECURSIVE grants AS (
+    SELECT descendantUuid, ascendantUuid, $5 AS level
+        FROM RbacGrants
+        WHERE assumed
+            AND ascendantUuid = any(subjectIds)
+    UNION ALL
+    SELECT g.descendantUuid, g.ascendantUuid, grants.level + $6 AS level
+        FROM RbacGrants g
+        INNER JOIN grants ON grants.descendantUuid = g.ascendantUuid
+        WHERE g.assumed
+),
+granted AS (
+    SELECT DISTINCT descendantUuid
+    FROM grants
+)
+SELECT DISTINCT perm.objectUuid
+    FROM granted
+    JOIN RbacPermission perm ON granted.descendantUuid = perm.uuid
+    JOIN RbacObject obj ON obj.uuid = perm.objectUuid
+    WHERE (requiredOp = $7 OR perm.op = requiredOp)
+        AND obj.objectTable = forObjectTable
+    LIMIT maxObjects+$8
+```
+
+That query is used to determine access rights of the currently active RBAC-subject(s).
+
+We used `EXPLAIN` with a concrete version (parameters substituted with real values) of that query and got this result:
+
+```
+QUERY PLAN
+Limit  (cost=6549.08..6549.35 rows=54 width=16)
+  CTE grants
+    ->  Recursive Union  (cost=4.32..5845.97 rows=1103 width=36)
+            ->  Bitmap Heap Scan on rbacgrants  (cost=4.32..15.84 rows=3 width=36)
+                  Recheck Cond: (ascendantuuid = ANY ('{ad1133dc-fbb7-43c9-8c20-0da3f89a2388}'::uuid[]))
+                  Filter: assumed
+                  ->  Bitmap Index Scan on rbacgrants_ascendantuuid_idx  (cost=0.00..4.32 rows=3 width=0)
+                         Index Cond: (ascendantuuid = ANY ('{ad1133dc-fbb7-43c9-8c20-0da3f89a2388}'::uuid[]))
+            ->  Nested Loop  (cost=0.29..580.81 rows=110 width=36)
+                  ->  WorkTable Scan on grants grants_1  (cost=0.00..0.60 rows=30 width=20)
+                  ->  Index Scan using rbacgrants_ascendantuuid_idx on rbacgrants g  (cost=0.29..19.29 rows=4 width=32)
+                        Index Cond: (ascendantuuid = grants_1.descendantuuid)
+                        Filter: assumed
+  ->  Unique  (cost=703.11..703.38 rows=54 width=16)
+        ->  Sort  (cost=703.11..703.25 rows=54 width=16)
+              Sort Key: perm.objectuuid
+              ->  Nested Loop  (cost=31.60..701.56 rows=54 width=16)
+                    ->  Hash Join  (cost=31.32..638.78 rows=200 width=16)
+                          Hash Cond: (perm.uuid = grants.descendantuuid)
+                            ->  Seq Scan on rbacpermission perm  (cost=0.00..532.92 rows=28392  width=32)
+                            ->  Hash  (cost=28.82..28.82 rows=200 width=16)
+                                  ->  HashAggregate  (cost=24.82..26.82 rows=200 width=16)
+                                        Group Key: grants.descendantuuid
+                                        ->  CTE Scan on grants  (cost=0.00..22.06 rows=1103 width=16)
+                    ->  Index Only Scan using rbacobject_objecttable_uuid_key on rbacobject obj  (cost=0.28..0.31 rows=1 width=16)
+                            Index Cond: ((objecttable = 'hs_hosting_asset'::text) AND (uuid = perm.objectuuid))
+```
+
+### Office-Relations-Query
+
+```SQL
+SELECT hore1_0.uuid,a1_0.uuid,a1_0.familyname,a1_0.givenname,a1_0.persontype,a1_0.salutation,a1_0.title,a1_0.tradename,a1_0.version,c1_0.uuid,c1_0.caption,c1_0.emailaddresses,c1_0.phonenumbers,c1_0.postaladdress,c1_0.version,h1_0.uuid,h1_0.familyname,h1_0.givenname,h1_0.persontype,h1_0.salutation,h1_0.title,h1_0.tradename,h1_0.version,hore1_0.mark,hore1_0.type,hore1_0.version 
+    FROM hs_office_relation_rv hore1_0
+    LEFT JOIN hs_office_person_rv a1_0 ON a1_0.uuid=hore1_0.anchoruuid 
+    LEFT JOIN hs_office_contact_rv c1_0 ON c1_0.uuid=hore1_0.contactuuid
+    LEFT JOIN hs_office_person_rv h1_0 ON h1_0.uuid=hore1_0.holderuuid
+    WHERE hore1_0.uuid=$1
+```
+
+That query into the `hs_office_relation_rv`-table is presumably the query to determine the partner of a debitor, which requires two of such queries each (Debitor -> Debitor-Relation -> Debitor-Anchor == Partner-Holder -> Partner-Relation -> Partner).
+
+### Total-Query-Time > Total-Import-Runtime
+
+That both queries total up to more than the runtime of the import-process is most likely due to internal parallel query processing.
+
+## Attempts to Mitigate the Problem
+
+### VACUUM ANALYZE
+
+In the middle of the import, we updated the PostgreSQL statistics to recalibrate the query optimizer:
+
+```SQL
+VACUUM ANALYZE;
+```
+
+This did not improve the performance.
+
+
+### Improving Indexes
+
+The sequentiap
+
+create index on RbacPermission (objectUuid, op);
+create index on RbacPermission (opTableName, op);
+
+###
+
+We were suspicious about the sequential scan over all `rbacpermission` rows which was done by PostgreSQL to execute a HashJoin strategy. Turning off that strategy by
+
+```SQL
+ALTER FUNCTION queryAccessibleObjectUuidsOfSubjectIds SET enable_hashjoin = off;
+```
+
+did not improve the performance though. The HashJoin was actually still applied, but no full table scan anymore:
+
+```
+[...]
+    QUERY PLAN
+    ->  Hash Join  (cost=36.02..40.78 rows=1 width=16)
+         Hash Cond: (grants.descendantuuid = perm.uuid)
+            ->  HashAggregate  (cost=13.32..15.32 rows=200 width=16)
+                    Group Key: grants.descendantuuid
+                        ->  CTE Scan on grants  (cost=0.00..11.84 rows=592 width=16)
+[...]
+```
+
+The HashJoin strategy could be great if the hash-map could be kept for multiple invocations. But during an import process, of course, there are always new rows in the underlying table and the hash-map would be outdated immediately.
+
+
+

docker-compose.yml

@@ -0,0 +1,19 @@
+version: '3.8'
+
+services:
+  postgres:
+    image: postgres-with-contrib:15.5-bookworm
+    container_name: custom-postgres
+    environment:
+      POSTGRES_PASSWORD: password
+    volumes:
+      - /home/mi/Projekte/Hostsharing/hsadmin-ng/etc/postgresql-log-slow-queries.conf:/etc/postgresql/postgresql.conf
+    ports:
+      - "5432:5432"
+    command:
+      - bash
+      - -c
+      - >
+        apt-get update &&
+        apt-get install -y postgresql-contrib &&
+        docker-entrypoint.sh postgres -c config_file=/etc/postgresql/postgresql.conf

etc/postgresql-log-slow-queries.conf

@@ -0,0 +1,10 @@
+shared_preload_libraries = 'pg_stat_statements,auto_explain'
+log_min_duration_statement = 1000
+log_statement = 'all'
+log_duration = on
+pg_stat_statements.track = all
+auto_explain.log_min_duration = '1s'  # Logs queries taking longer than 1 second
+auto_explain.log_analyze = on         # Include actual run times
+auto_explain.log_buffers = on         # Include buffer usage statistics
+auto_explain.log_format = 'json'      # Format the log output in JSON
+listen_addresses = '*'

src/main/resources/db/changelog/0-basis/090-log-slow-queries-extensions.sql

@@ -0,0 +1,13 @@
+--liquibase formatted sql
+
+
+-- ============================================================================
+-- PG-STAT-STATEMENTS-EXTENSION
+--changeset pg-stat-statements-extension:1 runOnChange=true endDelimiter:--//
+-- ----------------------------------------------------------------------------
+/*
+    Makes improved uuid generation available.
+ */
+create extension if not exists "pg_stat_statements";
+--//
+

src/main/resources/db/changelog/1-rbac/1050-rbac-base.sql

@@ -372,6 +372,8 @@ create table RbacPermission
     op          RbacOp not null,
     opTableName varchar(60)
 );
+create index on RbacPermission (objectUuid, op);
+create index on RbacPermission (opTableName, op);
 
 ALTER TABLE RbacPermission
     ADD CONSTRAINT RbacPermission_uc UNIQUE NULLS NOT DISTINCT (objectUuid, op, opTableName);
@@ -495,78 +497,68 @@ create index on RbacGrants (ascendantUuid);
 create index on RbacGrants (descendantUuid);
 
 call create_journal('RbacGrants');
-
 create or replace function findGrantees(grantedId uuid)
     returns setof RbacReference
     returns null on null input
     language sql as $$
-select reference.*
+with recursive grants as (
-    from (with recursive grants as (select descendantUuid,
+    select descendantUuid, ascendantUuid
-                                           ascendantUuid
+        from RbacGrants
-                                        from RbacGrants
+        where descendantUuid = grantedId
-                                        where descendantUuid = grantedId
+    union all
-                                    union all
+    select g.descendantUuid, g.ascendantUuid
-                                    select "grant".descendantUuid,
+        from RbacGrants g
-                                           "grant".ascendantUuid
+                 inner join grants on grants.ascendantUuid = g.descendantUuid
-                                        from RbacGrants "grant"
+)
-                                                 inner join grants recur on recur.ascendantUuid = "grant".descendantUuid)
+select ref.*
-          select ascendantUuid
+    from grants
-              from grants) as grantee
+             join RbacReference ref on ref.uuid = grants.ascendantUuid;
-             join RbacReference reference on reference.uuid = grantee.ascendantUuid;
+$$;
+
+create or replace function isGranted(granteeIds uuid[], grantedId uuid)
+    returns bool
+    returns null on null input
+    language sql as $$
+with recursive grants as (
+    select descendantUuid, ascendantUuid
+        from RbacGrants
+        where descendantUuid = grantedId
+    union all
+    select "grant".descendantUuid, "grant".ascendantUuid
+        from RbacGrants "grant"
+                 inner join grants recur on recur.ascendantUuid = "grant".descendantUuid
+)
+select exists (
+    select true
+        from grants
+        where ascendantUuid = any(granteeIds)
+) or grantedId = any(granteeIds);
 $$;
 
 create or replace function isGranted(granteeId uuid, grantedId uuid)
     returns bool
     returns null on null input
     language sql as $$
-select granteeId = grantedId or granteeId in (with recursive grants as (select descendantUuid, ascendantUuid
+select * from isGranted(array[granteeId], grantedId);
-                                                                            from RbacGrants
-                                                                            where descendantUuid = grantedId
-                                                                        union all
-                                                                        select "grant".descendantUuid, "grant".ascendantUuid
-                                                                            from RbacGrants "grant"
-                                                                                     inner join grants recur on recur.ascendantUuid = "grant".descendantUuid)
-                                              select ascendantUuid
-                                                  from grants);
 $$;
-
-create or replace function isGranted(granteeIds uuid[], grantedId uuid)
-    returns bool
-    returns null on null input
-    language plpgsql as $$
-declare
-    granteeId uuid;
-begin
-    -- TODO.perf: needs optimization
-    foreach granteeId in array granteeIds
-        loop
-            if isGranted(granteeId, grantedId) then
-                return true;
-            end if;
-        end loop;
-    return false;
-end; $$;
-
 create or replace function isPermissionGrantedToSubject(permissionId uuid, subjectId uuid)
     returns BOOL
     stable -- leakproof
     language sql as $$
+with recursive grants as (
+    select descendantUuid, ascendantUuid
+        from RbacGrants
+        where descendantUuid = permissionId
+    union all
+    select g.descendantUuid, g.ascendantUuid
+        from RbacGrants g
+                 inner join grants on grants.ascendantUuid = g.descendantUuid
+)
 select exists(
-           select *
+    select true
-               from RbacUser
+        from grants
-               where uuid in (with recursive grants as (select descendantUuid,
+        where ascendantUuid = subjectId
-                                                               ascendantUuid
+);
-                                                            from RbacGrants g
-                                                            where g.descendantUuid = permissionId
-                                                        union all
-                                                        select g.descendantUuid,
-                                                               g.ascendantUuid
-                                                            from RbacGrants g
-                                                                     inner join grants recur on recur.ascendantUuid = g.descendantUuid)
-                              select ascendantUuid
-                                  from grants
-                                  where ascendantUuid = subjectId)
-           );
 $$;
 
 create or replace function hasInsertPermission(objectUuid uuid, tableName text )
@@ -708,14 +700,14 @@ begin
 end; $$;
 
 -- ============================================================================
---changeset rbac-base-QUERY-ACCESSIBLE-OBJECT-UUIDS:1 endDelimiter:--//
+--changeset rbac-base-QUERY-ACCESSIBLE-OBJECT-UUIDS:1 runOnChange=true endDelimiter:--//
 -- ----------------------------------------------------------------------------
 /*
 
  */
 create or replace function queryAccessibleObjectUuidsOfSubjectIds(
     requiredOp RbacOp,
-    forObjectTable varchar, -- reduces the result set, but is not really faster when used in restricted view
+    forObjectTable varchar,
     subjectIds uuid[],
     maxObjects integer = 8000)
     returns setof uuid
@@ -724,23 +716,29 @@ create or replace function queryAccessibleObjectUuidsOfSubjectIds(
 declare
     foundRows bigint;
 begin
-    return query select distinct perm.objectUuid
+    return query
-                     from (with recursive grants as (select descendantUuid, ascendantUuid, 1 as level
+        WITH RECURSIVE grants AS (
-                                                         from RbacGrants
+            SELECT descendantUuid, ascendantUuid, 1 AS level
-                                                         where assumed
+                FROM RbacGrants
-                                                           and ascendantUuid = any (subjectIds)
+                WHERE assumed
-                                                     union
+                  AND ascendantUuid = any(subjectIds)
-                                                     distinct
+            UNION ALL
-                                                     select "grant".descendantUuid, "grant".ascendantUuid, level + 1 as level
+            SELECT g.descendantUuid, g.ascendantUuid, grants.level + 1 AS level
-                                                         from RbacGrants "grant"
+                FROM RbacGrants g
-                                                                  inner join grants recur on recur.descendantUuid = "grant".ascendantUuid
+                         INNER JOIN grants ON grants.descendantUuid = g.ascendantUuid
-                                                         where assumed)
+                WHERE g.assumed
-                           select descendantUuid
+        ),
-                               from grants) as granted
+                       granted AS (
-                              join RbacPermission perm
+                           SELECT DISTINCT descendantUuid
-                                   on granted.descendantUuid = perm.uuid and (requiredOp = 'SELECT' or perm.op = requiredOp)
+                               FROM grants
-                              join RbacObject obj on obj.uuid = perm.objectUuid and obj.objectTable = forObjectTable
+                       )
-                     limit maxObjects + 1;
+        SELECT DISTINCT perm.objectUuid
+            FROM granted
+                     JOIN RbacPermission perm ON granted.descendantUuid = perm.uuid
+                     JOIN RbacObject obj ON obj.uuid = perm.objectUuid
+            WHERE (requiredOp = 'SELECT' OR perm.op = requiredOp)
+              AND obj.objectTable = forObjectTable
+            LIMIT maxObjects+1;
 
     foundRows = lastRowCount();
     if foundRows > maxObjects then
@@ -751,7 +749,7 @@ begin
     end if;
 end;
 $$;
-
+ALTER FUNCTION queryAccessibleObjectUuidsOfSubjectIds SET enable_hashjoin = off;
 --//
 
 -- ============================================================================
@@ -764,24 +762,23 @@ create or replace function queryPermissionsGrantedToSubjectId(subjectId uuid)
     returns setof RbacPermission
     strict
     language sql as $$
-    -- @formatter:off
+with recursive grants as (
-select *
+    select descendantUuid, ascendantUuid
-    from RbacPermission
+        from RbacGrants
-    where uuid in (
+        where ascendantUuid = subjectId
-            with recursive grants as (
+    union all
-                select distinct descendantUuid, ascendantUuid
+    select g.descendantUuid, g.ascendantUuid
-                    from RbacGrants
+        from RbacGrants g
-                    where ascendantUuid = subjectId
+                 inner join grants on grants.descendantUuid = g.ascendantUuid
-                union all
+)
-                select "grant".descendantUuid, "grant".ascendantUuid
+select perm.*
-                    from RbacGrants "grant"
+    from RbacPermission perm
-                    inner join grants recur on recur.descendantUuid = "grant".ascendantUuid
+    where perm.uuid in (
-            )
+        select descendantUuid
-            select descendantUuid
+            from grants
-                from grants
+    );
-        );
--- @formatter:on
 $$;
+
 --//
 
 -- ============================================================================

src/main/resources/db/changelog/7-hs-hosting/701-hosting-asset/7010-hs-hosting-asset.sql

@@ -44,6 +44,8 @@ create table if not exists hs_hosting_asset
     constraint chk_hs_hosting_asset_has_booking_item_or_parent_asset
         check (bookingItemUuid is not null or parentAssetUuid is not null or type in ('DOMAIN_SETUP', 'IPV4_NUMBER', 'IPV6_NUMBER'))
 );
+-- create index on hs_hosting_asset (identifier);
+-- create index on hs_hosting_asset (type);
 --//
 
 

src/main/resources/db/changelog/db.changelog-master.yaml

@@ -21,6 +21,8 @@ databaseChangeLog:
         file: db/changelog/0-basis/010-context.sql
     - include:
         file: db/changelog/0-basis/020-audit-log.sql
+    - include:
+        file: db/changelog/0-basis/090-log-slow-queries-extensions.sql
     - include:
         file: db/changelog/1-rbac/1050-rbac-base.sql
     - include:

src/test/resources/application.yml

@@ -28,7 +28,7 @@ spring:
         change-log: classpath:/db/changelog/db.changelog-master.yaml
         contexts: tc,test,dev
 
-logging:
+#logging:
-    level:
+#    level:
-        liquibase: INFO
+#        liquibase: INFO
-        net.ttddyy.dsproxy.listener: DEBUG
+#        net.ttddyy.dsproxy.listener: DEBUG