trustification / trustify

Apache License 2.0
10 stars 19 forks source link

poorly performing query when hitting api/v1/purl/{uuid} #837

Closed JimFuller-RedHat closed 1 month ago

JimFuller-RedHat commented 1 month ago

At scale, hitting api/v1/purl/{uuid} blows up

1232024-09-20T14:11:27.271481Z  INFO actix_web::middleware::logger: ::1 "GET /api/v1/purl/8543edb3-05b9-5b64-a438-c7af4c58cd65 HTTP/1.1" 200 1782 "http://localhost:8080/packages/8543edb3-05b9-5b64-a438-c7af4c58cd65" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36" 0.082499    
2024-09-20T14:11:33.068435Z  WARN sqlx::query: slow statement: execution time exceeded alert threshold summary="SELECT array_agg(DISTINCT status.slug) AS …" db.statement="\n\nSELECT\n  array_agg(DISTINCT status.slug) AS \"statuses\",\n  \"purl_status\".\"advisory_id\",\n  \"context_cpe\".\"id\" AS \"context_cpe$id\",\n  \"context_cpe\".\"part\" AS \"context_cpe$part\",\n  \"context_cpe\".\"vendor\" AS \"context_cpe$vendor\",\n  \"context_cpe\".\"product\" AS \"context_cpe$product\",\n  \"context_cpe\".\"version\" AS \"context_cpe$version\",\n  \"context_cpe\".\"update\" AS \"context_cpe$update\",\n  \"context_cpe\".\"edition\" AS \"context_cpe$edition\",\n  \"context_cpe\".\"language\" AS \"context_cpe$language\",\n  \"sbom\".\"sbom_id\" AS \"sbom$sbom_id\",\n  \"sbom\".\"node_id\" AS \"sbom$node_id\",\n  \"sbom\".\"document_id\" AS \"sbom$document_id\",\n  \"sbom\".\"published\" AS \"sbom$published\",\n  \"sbom\".\"authors\" AS \"sbom$authors\",\n  \"sbom\".\"source_document_id\" AS \"sbom$source_document_id\",\n  \"sbom\".\"labels\" AS \"sbom$labels\",\n  \"sbom_package\".\"sbom_id\" AS \"sbom_package$sbom_id\",\n  \"sbom_package\".\"node_id\" AS \"sbom_package$node_id\",\n  \"sbom_package\".\"version\" AS \"sbom_package$version\",\n  \"sbom_node\".\"sbom_id\" AS \"sbom_node$sbom_id\",\n  \"sbom_node\".\"node_id\" AS \"sbom_node$node_id\",\n  \"sbom_node\".\"name\" AS \"sbom_node$name\",\n  \"cpe\".\"id\" AS \"cpe$id\",\n  \"cpe\".\"part\" AS \"cpe$part\",\n  \"cpe\".\"vendor\" AS \"cpe$vendor\",\n  \"cpe\".\"product\" AS \"cpe$product\",\n  \"cpe\".\"version\" AS \"cpe$version\",\n  \"cpe\".\"update\" AS \"cpe$update\",\n  \"cpe\".\"edition\" AS \"cpe$edition\",\n  \"cpe\".\"language\" AS \"cpe$language\"\nFROM\n  \"sbom_package_purl_ref\"\n  LEFT JOIN \"qualified_purl\" ON \"sbom_package_purl_ref\".\"qualified_purl_id\" = \"qualified_purl\".\"id\"\n  LEFT JOIN \"versioned_purl\" ON \"qualified_purl\".\"versioned_purl_id\" = \"versioned_purl\".\"id\"\n  LEFT JOIN \"base_purl\" ON \"versioned_purl\".\"base_purl_id\" = \"base_purl\".\"id\"\n  LEFT JOIN \"purl_status\" ON \"base_purl\".\"id\" = \"purl_status\".\"base_purl_id\"\n  JOIN \"version_range\" ON \"purl_status\".\"version_range_id\" = \"version_range\".\"id\"\n  JOIN \"status\" ON \"purl_status\".\"status_id\" = \"status\".\"id\"\n  LEFT JOIN \"cpe\" AS \"context_cpe\" ON \"purl_status\".\"context_cpe_id\" = \"context_cpe\".\"id\"\n  JOIN \"sbom\" ON \"sbom_package_purl_ref\".\"sbom_id\" = \"sbom\".\"sbom_id\"\n  LEFT JOIN \"sbom_node\" ON \"sbom\".\"sbom_id\" = \"sbom_node\".\"sbom_id\"\n  AND \"sbom_node\".\"sbom_id\" = \"sbom\".\"sbom_id\"\n  JOIN \"sbom_package\" ON \"sbom_node\".\"sbom_id\" = \"sbom_package\".\"sbom_id\"\n  AND \"sbom_node\".\"node_id\" = \"sbom_package\".\"node_id\"\n  JOIN \"sbom_package_cpe_ref\" ON \"sbom_package\".\"sbom_id\" = \"sbom_package_cpe_ref\".\"sbom_id\"\n  AND \"sbom_package\".\"node_id\" = \"sbom_package_cpe_ref\".\"node_id\"\n  JOIN \"cpe\" ON \"sbom_package_cpe_ref\".\"cpe_id\" = \"cpe\".\"id\"\nWHERE\n  \"purl_status\".\"vulnerability_id\" = $1\n  AND version_matches(\"versioned_purl\".\"version\", \"version_range\".*)\nGROUP BY\n  \"context_cpe\".\"id\",\n  \"sbom\".\"sbom_id\",\n  \"sbom_node\".\"sbom_id\",\n  \"sbom_node\".\"node_id\",\n  \"purl_status\".\"advisory_id\",\n  \"sbom_package\".\"sbom_id\",\n  \"sbom_package\".\"node_id\",\n  \"cpe\".\"id\"\n" rows_affected=54645 rows_returned=54645 elapsed=5.610630417s elapsed_secs=5.610630417 slow_threshold=1s

The cleaned up SQL query looks like:

SELECT
  array_agg(DISTINCT status.slug) AS "statuses",
  "purl_status"."advisory_id",
  "context_cpe"."id" AS "context_cpe$id",
  "context_cpe"."part" AS "context_cpe$part",
  "context_cpe"."vendor" AS "context_cpe$vendor",
  "context_cpe"."product" AS "context_cpe$product",
  "context_cpe"."version" AS "context_cpe$version",
  "context_cpe"."update" AS "context_cpe$update",
  "context_cpe"."edition" AS "context_cpe$edition",
  "context_cpe"."language" AS "context_cpe$language",
  "sbom"."sbom_id" AS "sbom$sbom_id",
  "sbom"."node_id" AS "sbom$node_id",
  "sbom"."document_id" AS "sbom$document_id",
  "sbom"."published" AS "sbom$published",
  "sbom"."authors" AS "sbom$authors",
  "sbom"."source_document_id" AS "sbom$source_document_id",
  "sbom"."labels" AS "sbom$labels",
  "sbom_package"."sbom_id" AS "sbom_package$sbom_id",
  "sbom_package"."node_id" AS "sbom_package$node_id",
  "sbom_package"."version" AS "sbom_package$version",
  "sbom_node"."sbom_id" AS "sbom_node$sbom_id",
  "sbom_node"."node_id" AS "sbom_node$node_id",
  "sbom_node"."name" AS "sbom_node$name",
  "cpe"."id" AS "cpe$id",
  "cpe"."part" AS "cpe$part",
  "cpe"."vendor" AS "cpe$vendor",
  "cpe"."product" AS "cpe$product",
  "cpe"."version" AS "cpe$version",
  "cpe"."update" AS "cpe$update",
  "cpe"."edition" AS "cpe$edition",
  "cpe"."language" AS "cpe$language"
FROM
  "sbom_package_purl_ref"
  LEFT JOIN "qualified_purl" ON "sbom_package_purl_ref"."qualified_purl_id" = "qualified_purl"."id"
  LEFT JOIN "versioned_purl" ON "qualified_purl"."versioned_purl_id" = "versioned_purl"."id"
  LEFT JOIN "base_purl" ON "versioned_purl"."base_purl_id" = "base_purl"."id"
  LEFT JOIN "purl_status" ON "base_purl"."id" = "purl_status"."base_purl_id"
  JOIN "version_range" ON "purl_status"."version_range_id" = "version_range"."id"
  JOIN "status" ON "purl_status"."status_id" = "status"."id"
  LEFT JOIN "cpe" AS "context_cpe" ON "purl_status"."context_cpe_id" = "context_cpe"."id"
  JOIN "sbom" ON "sbom_package_purl_ref"."sbom_id" = "sbom"."sbom_id"
  LEFT JOIN "sbom_node" ON "sbom"."sbom_id" = "sbom_node"."sbom_id"
  AND "sbom_node"."sbom_id" = "sbom"."sbom_id"
  JOIN "sbom_package" ON "sbom_node"."sbom_id" = "sbom_package"."sbom_id"
  AND "sbom_node"."node_id" = "sbom_package"."node_id"
  JOIN "sbom_package_cpe_ref" ON "sbom_package"."sbom_id" = "sbom_package_cpe_ref"."sbom_id"
  AND "sbom_package"."node_id" = "sbom_package_cpe_ref"."node_id"
  JOIN "cpe" ON "sbom_package_cpe_ref"."cpe_id" = "cpe"."id"
WHERE
  "purl_status"."vulnerability_id" = $1
  AND version_matches("versioned_purl"."version", "version_range".*)
GROUP BY
  "context_cpe"."id",
  "sbom"."sbom_id",
  "sbom_node"."sbom_id",
  "sbom_node"."node_id",
  "purl_status"."advisory_id",
  "sbom_package"."sbom_id",
  "sbom_package"."node_id",
  "cpe"."id";

There maybe some relation to /api/v1/vulnerability/{CVE-###-####}

12345672024-09-20T14:11:36.860933Z  INFO actix_web::middleware::logger: ::1 "GET /api/v1/vulnerability/CVE-2023-2974 HTTP/1.1" 200 32708 "http://localhost:8080/packages/8543edb3-05b9-5b64-a438-c7af4c58cd65" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36" 9.582379    
2024-09-20T14:11:36.987133Z  INFO actix_web::middleware::logger: ::1 "GET /api/v1/vulnerability/CVE-2023-1584 HTTP/1.1" 200 33064 "http://localhost:8080/packages/8543edb3-05b9-5b64-a438-c7af4c58cd65" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36" 9.708664    
2024-09-20T14:11:37.246366Z  INFO actix_web::middleware::logger: ::1 "GET /api/v1/vulnerability/CVE-2023-0481 HTTP/1.1" 200 32842 "http://localhost:8080/packages/8543edb3-05b9-5b64-a438-c7af4c58cd65" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36" 9.969206    
2024-09-20T14:11:37.253718Z  INFO actix_web::middleware::logger: ::1 "GET /api/v1/vulnerability/CVE-2023-28867 HTTP/1.1" 200 32962 "http://localhost:8080/packages/8543edb3-05b9-5b64-a438-c7af4c58cd65" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36" 9.975239    
2024-09-20T14:11:37.484922Z  INFO actix_web::middleware::logger: ::1 "GET /api/v1/vulnerability/CVE-2022-45787 HTTP/1.1" 200 38855 "http://localhost:8080/packages/8543edb3-05b9-5b64-a438-c7af4c58cd65" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36" 10.206420   

Note - this poor performance was originally 'masked' by subtransactions error.

JimFuller-RedHat commented 1 month ago

query plan looks quite chunky ... the grouping causes the sorting, which hits disk especially for highly used packages ... making things sluggish ... when we do https://github.com/trustification/trustify/issues/771 this query plan hopefully will get significantly simpler (and better performing).

+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| QUERY PLAN                                                                                                                                                                                       |
|--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------|
| GroupAggregate  (cost=103110.40..106505.59 rows=113173 width=737) (actual time=2873.068..3005.622 rows=62887 loops=1)                                                                            |
|   Group Key: context_cpe.id, sbom.sbom_id, sbom_node.node_id, purl_status.advisory_id, cpe.id                                                                                                    |
|   ->  Sort  (cost=103110.40..103393.34 rows=113173 width=716) (actual time=2873.026..2946.514 rows=302432 loops=1)                                                                               |
|         Sort Key: context_cpe.id, sbom.sbom_id, sbom_node.node_id, purl_status.advisory_id, cpe.id, status.slug                                                                                  |
|         Sort Method: external merge  Disk: 207976kB                                                                                                                                              |
|         ->  Hash Join  (cost=44664.14..51466.67 rows=113173 width=716) (actual time=1476.102..2094.196 rows=302432 loops=1)                                                                      |
|               Hash Cond: (sbom_package_purl_ref.sbom_id = sbom.sbom_id)                                                                                                                          |
|               ->  Nested Loop  (cost=689.63..6198.17 rows=9272 width=98) (actual time=5.225..190.874 rows=8416 loops=1)                                                                          |
|                     ->  Nested Loop  (cost=689.20..3774.40 rows=2447 width=98) (actual time=5.207..168.819 rows=3149 loops=1)                                                                    |
|                           ->  Hash Join  (cost=688.78..2886.05 rows=1672 width=98) (actual time=5.190..158.664 rows=1578 loops=1)                                                                |
|                                 Hash Cond: (purl_status.version_range_id = version_range.id)                                                                                                     |
|                                 Join Filter: version_matches((versioned_purl.version)::text, version_range.*)                                                                                    |
|                                 Rows Removed by Join Filter: 6101                                                                                                                                |
|                                 ->  Nested Loop  (cost=32.49..2216.59 rows=5017 width=134) (actual time=0.458..19.209 rows=7679 loops=1)                                                         |
|                                       ->  Hash Left Join  (cost=32.06..1367.71 rows=880 width=130) (actual time=0.449..6.447 rows=880 loops=1)                                                   |
|                                             Hash Cond: (purl_status.context_cpe_id = context_cpe.id)                                                                                             |
|                                             ->  Hash Join  (cost=1.56..1334.89 rows=880 width=91) (actual time=0.306..6.084 rows=880 loops=1)                                                    |
|                                                   Hash Cond: (purl_status.status_id = status.id)                                                                                                 |
|                                                   ->  Nested Loop  (cost=0.43..1329.81 rows=880 width=96) (actual time=0.293..5.888 rows=880 loops=1)                                            |
|                                                         ->  Seq Scan on purl_status  (cost=0.00..496.94 rows=880 width=80) (actual time=0.281..2.098 rows=880 loops=1)                           |
|                                                               Filter: ((vulnerability_id)::text = 'CVE-2023-28867'::text)                                                                        |
|                                                               Rows Removed by Filter: 15755                                                                                                      |
|                                                         ->  Memoize  (cost=0.43..1.04 rows=1 width=16) (actual time=0.004..0.004 rows=1 loops=880)                                               |
|                                                               Cache Key: purl_status.base_purl_id                                                                                                |
|                                                               Cache Mode: logical                                                                                                                |
|                                                               Hits: 1  Misses: 879  Evictions: 0  Overflows: 0  Memory Usage: 110kB                                                              |
|                                                               ->  Index Only Scan using package_pkey on base_purl  (cost=0.42..1.03 rows=1 width=16) (actual time=0.003..0.003 rows=1 loops=879) |
|                                                                     Index Cond: (id = purl_status.base_purl_id)                                                                                  |
|                                                                     Heap Fetches: 0                                                                                                              |
|                                                   ->  Hash  (cost=1.06..1.06 rows=6 width=27) (actual time=0.008..0.010 rows=6 loops=1)                                                          |
|                                                         Buckets: 1024  Batches: 1  Memory Usage: 9kB                                                                                             |
|                                                         ->  Seq Scan on status  (cost=0.00..1.06 rows=6 width=27) (actual time=0.006..0.007 rows=6 loops=1)                                      |
|                                             ->  Hash  (cost=23.00..23.00 rows=600 width=55) (actual time=0.139..0.140 rows=600 loops=1)                                                          |
|                                                   Buckets: 1024  Batches: 1  Memory Usage: 60kB                                                                                                  |
|                                                   ->  Seq Scan on cpe context_cpe  (cost=0.00..23.00 rows=600 width=55) (actual time=0.004..0.075 rows=600 loops=1)                              |
|                                       ->  Index Scan using by_pid_v on versioned_purl  (cost=0.42..0.81 rows=15 width=52) (actual time=0.006..0.013 rows=9 loops=880)                            |
|                                             Index Cond: (base_purl_id = base_purl.id)                                                                                                            |
|                                 ->  Hash  (cost=448.35..448.35 rows=16635 width=144) (actual time=4.589..4.590 rows=16635 loops=1)                                                               |
|                                       Buckets: 32768  Batches: 1  Memory Usage: 3107kB                                                                                                           |
|                                       ->  Seq Scan on version_range  (cost=0.00..448.35 rows=16635 width=144) (actual time=0.008..3.157 rows=16635 loops=1)                                      |
|                           ->  Index Scan using by_pvid on qualified_purl  (cost=0.42..0.50 rows=3 width=32) (actual time=0.005..0.006 rows=2 loops=1578)                                         |
|                                 Index Cond: (versioned_purl_id = versioned_purl.id)                                                                                                              |
|                     ->  Index Scan using sbom_package_purl_ref_qual_purl_id_idx on sbom_package_purl_ref  (cost=0.43..0.81 rows=18 width=32) (actual time=0.005..0.007 rows=3 loops=3149)        |
|                           Index Cond: (qualified_purl_id = qualified_purl.id)                                                                                                                    |
|               ->  Hash  (cost=43881.90..43881.90 rows=7409 width=650) (actual time=1469.320..1469.336 rows=250537 loops=1)                                                                       |
|                     Buckets: 16384 (originally 8192)  Batches: 128 (originally 1)  Memory Usage: 15800kB                                                                                         |
|                     ->  Nested Loop  (cost=144.06..43881.90 rows=7409 width=650) (actual time=0.467..1286.483 rows=250537 loops=1)                                                               |
|                           ->  Nested Loop  (cost=143.78..43588.91 rows=7409 width=611) (actual time=0.458..1207.729 rows=250537 loops=1)                                                         |
|                                 Join Filter: (sbom.sbom_id = sbom_package.sbom_id)                                                                                                               |
|                                 ->  Hash Join  (cost=143.22..38935.28 rows=7496 width=582) (actual time=0.442..418.925 rows=250537 loops=1)                                                      |
|                                       Hash Cond: (sbom_node.sbom_id = sbom.sbom_id)                                                                                                              |
|                                       ->  Nested Loop  (cost=0.57..38624.63 rows=63553 width=164) (actual time=0.029..379.296 rows=250537 loops=1)                                               |
|                                             ->  Seq Scan on sbom_package_cpe_ref  (cost=0.00..5856.37 rows=250537 width=77) (actual time=0.006..23.059 rows=250537 loops=1)                      |
|                                             ->  Memoize  (cost=0.57..1.07 rows=1 width=87) (actual time=0.001..0.001 rows=1 loops=250537)                                                        |
|                                                   Cache Key: sbom_package_cpe_ref.sbom_id, sbom_package_cpe_ref.node_id                                                                          |
|                                                   Cache Mode: logical                                                                                                                            |
|                                                   Hits: 192408  Misses: 58129  Evictions: 22400  Overflows: 0  Memory Usage: 8193kB                                                              |
|                                                   ->  Index Scan using sbom_node_pkey on sbom_node  (cost=0.56..1.06 rows=1 width=87) (actual time=0.004..0.004 rows=1 loops=58129)              |
|                                                         Index Cond: ((sbom_id = sbom_package_cpe_ref.sbom_id) AND ((node_id)::text = (sbom_package_cpe_ref.node_id)::text))                      |
|                                       ->  Hash  (cost=135.07..135.07 rows=607 width=418) (actual time=0.409..0.410 rows=607 loops=1)                                                             |
|                                             Buckets: 1024  Batches: 1  Memory Usage: 279kB                                                                                                       |
|                                             ->  Seq Scan on sbom  (cost=0.00..135.07 rows=607 width=418) (actual time=0.006..0.339 rows=607 loops=1)                                             |
|                                 ->  Index Scan using sbom_package_pkey on sbom_package  (cost=0.56..0.61 rows=1 width=74) (actual time=0.003..0.003 rows=1 loops=250537)                         |
|                                       Index Cond: ((sbom_id = sbom_node.sbom_id) AND ((node_id)::text = (sbom_node.node_id)::text))                                                              |
|                           ->  Memoize  (cost=0.29..0.30 rows=1 width=55) (actual time=0.000..0.000 rows=1 loops=250537)                                                                          |
|                                 Cache Key: sbom_package_cpe_ref.cpe_id                                                                                                                           |
|                                 Cache Mode: logical                                                                                                                                              |
|                                 Hits: 249959  Misses: 578  Evictions: 0  Overflows: 0  Memory Usage: 95kB                                                                                        |
|                                 ->  Index Scan using cpe_pkey on cpe  (cost=0.28..0.29 rows=1 width=55) (actual time=0.002..0.002 rows=1 loops=578)                                              |
|                                       Index Cond: (id = sbom_package_cpe_ref.cpe_id)                                                                                                             |
| Planning Time: 3.758 ms                                                                                                                                                                          |
| Execution Time: 3043.479 ms       
JimFuller-RedHat commented 1 month ago

Can confirm adding indexes on id for all three purl tables mitigates eg. explain analyze on these slow queries show indexes being used - though until we resolve purl from jsonb column this kind of problem will continue (that is the subject of other ongoing work looking at query.rs).