Long response times while fetching DataSource and ExecutionEvents

[abhishekshenoy]

Below consumer endpoints are taking a lot of time to return results which makes our Spline UI very slow , we have performed a basic analysis and wanted to understand how we can improve the performance.

• http://localhost:8080/rest-gateway/consumer/execution-events (26s to fetch execution events for last 20 days)
• http://localhost:8080/rest-gateway/consumer/data-sources (Spline Fails with Async Timeout , takes 250s when fired directly on Arango for a query to fetch data of last 20 days )

We are using spline 0.6.1 which is deployed on Kubernetes and have a 3 node arango setup (n1-standard 32 GCP computes with 1TB ssd disks to store documents)

Below is the count of documents in each of the collection which are part of the queries to retrieve ExecutionEvents and DataSources.

• progress : 266486
• progressOf : 266487
• executionPlan : 280379
• affects : 280380
• datasource : 128225

So we proceeded to perform profiling of the queries which get executed in Arango and observed 2 scenarios.

Query to fetch execution events in Arango but takes 25s for spline to successfully receive a response.

Time taken by spline to retrieve results

Arango Query Profile

Query String (1438 chars, cacheable: false):
 WITH progress
 FOR ee IN progress
     FILTER ee._created <= 1642701767328
        AND ee.timestamp >= 1640973972444
        AND ee.timestamp <= 1642701725804
     FILTER IS_NULL(null) OR null == ee.extra.appId
     FILTER IS_NULL(null) OR null == ee.execPlanDetails.dataSourceUri
     FILTER IS_NULL(null)   OR null  == ee.execPlanDetails.append
     FILTER IS_NULL(null)
             OR null == ee.timestamp
             OR CONTAINS(LOWER(ee.execPlanDetails.frameworkName), null)
             OR CONTAINS(LOWER(ee.execPlanDetails.applicationName), null)
             OR CONTAINS(LOWER(ee.extra.appId), null)
             OR CONTAINS(LOWER(ee.execPlanDetails.dataSourceUri), null)
             OR CONTAINS(LOWER(ee.execPlanDetails.dataSourceType), null)
     LET resItem = {
         "executionEventId" : ee._key,
         "executionPlanId"  : ee.execPlanDetails.executionPlanKey,
         "frameworkName"    : ee.execPlanDetails.frameworkName,
         "applicationName"  : ee.execPlanDetails.applicationName,
         "ap...

Execution plan:
 Id   NodeType          Site  Calls    Items   Runtime [s]   Comment
  1   SingletonNode     DBS       1        1       0.00001   * ROOT
 18   IndexNode         DBS     139   138932      16.71788     - FOR ee IN progress   /* reverse persistent index scan, projections: `_key`, `extra`, `_created`, `execPlanDetails`, `timestamp`, 1 shard(s) */    
  3   CalculationNode   DBS     139   138932       0.13597       - LET #2 = ((((ee.`_created` <= 1642701767328) && (ee.`timestamp` >= 1640973972444)) && (ee.`timestamp` <= 1642701725804)) && (((null == null) || (ee.`extra`.`appId` == null)) && (((null == null) || (ee.`execPlanDetails`.`dataSourceUri` == null)) && (((null == null) || (ee.`execPlanDetails`.`append` == null)) && (((((((null == null) || (ee.`timestamp` == null)) || CONTAINS(LOWER(ee.`execPlanDetails`.`frameworkName`), null)) || CONTAINS(LOWER(ee.`execPlanDetails`.`applicationName`), null)) || CONTAINS(LOWER(ee.`extra`.`appId`), null)) || CONTAINS(LOWER(ee.`execPlanDetails`.`dataSourceUri`), null)) || CONTAINS(LOWER(ee.`execPlanDetails`.`dataSourceType`), null))))))   /* simple expression */   /* collections used: ee : progress */
  4   FilterNode        DBS     139   138932       0.07545       - FILTER #2
 14   CalculationNode   DBS     139   138932       0.02617       - LET #12 = ee.`timestamp`   /* attribute expression */   /* collections used: ee : progress */
 13   CalculationNode   DBS     139   138932      10.00189       - LET resItem = { "executionEventId" : ee.`_key`, "executionPlanId" : ee.`execPlanDetails`.`executionPlanKey`, "frameworkName" : ee.`execPlanDetails`.`frameworkName`, "applicationName" : ee.`execPlanDetails`.`applicationName`, "applicationId" : ee.`extra`.`appId`, "timestamp" : ee.`timestamp`, "dataSourceName" : REGEX_MATCHES(ee.`execPlanDetails`.`dataSourceUri`, "([^/]+)/*$")[1], "dataSourceUri" : ee.`execPlanDetails`.`dataSourceUri`, "dataSourceType" : ee.`execPlanDetails`.`dataSourceType`, "append" : ee.`execPlanDetails`.`append` }   /* simple expression */   /* collections used: ee : progress */
 15   SortNode          DBS       1       20       0.02012       - SORT #12 DESC   /* sorting strategy: constrained heap */
 21   RemoteNode        COOR      2       20       0.00058       - REMOTE
 22   GatherNode        COOR      2       20       0.00009       - GATHER   /* unsorted */
 16   LimitNode         COOR      2       10       0.00001       - LIMIT 10, 10
 17   ReturnNode        COOR      2       10       0.00001       - RETURN resItem

Indexes used:
 By   Name                      Type         Collection   Unique   Sparse   Selectivity   Fields                                Ranges
 18   idx_1714935113405431817   persistent   progress     false    false        99.98 %   [ `timestamp` ]                       ((ee.`timestamp` >= 1640973972444) && (ee.`timestamp` <= 1642701725804))
 18   idx_1714935113405431817   persistent   progress     false    false        99.98 %   [ `timestamp` ]                       ((ee.`timestamp` >= 1640973972444) && (ee.`timestamp` <= 1642701725804))
 18   idx_1714935113407528968   persistent   progress     false    false        18.20 %   [ `execPlanDetails.dataSourceUri` ]   (ee.`execPlanDetails`.`dataSourceUri` == null)
 18   idx_1714935113407528968   persistent   progress     false    false        18.20 %   [ `execPlanDetails.dataSourceUri` ]   (ee.`execPlanDetails`.`dataSourceUri` == null)
 18   idx_1714935113405431817   persistent   progress     false    false        99.98 %   [ `timestamp` ]                       ((ee.`timestamp` >= 1640973972444) && (ee.`timestamp` <= 1642701725804))
 18   idx_1714935113405431817   persistent   progress     false    false        99.98 %   [ `timestamp` ]                       ((ee.`timestamp` >= 1640973972444) && (ee.`timestamp` <= 1642701725804))
 18   idx_1714935113405431817   persistent   progress     false    false        99.98 %   [ `timestamp` ]                       ((ee.`timestamp` >= 1640973972444) && (ee.`timestamp` <= 1642701725804))
 18   idx_1714935113405431817   persistent   progress     false    false        99.98 %   [ `timestamp` ]                       ((ee.`timestamp` >= 1640973972444) && (ee.`timestamp` <= 1642701725804))
 18   idx_1714935113405431817   persistent   progress     false    false        99.98 %   [ `timestamp` ]                       ((ee.`timestamp` >= 1640973972444) && (ee.`timestamp` <= 1642701725804))
 18   idx_1714935113405431817   persistent   progress     false    false        99.98 %   [ `timestamp` ]                       ((ee.`timestamp` >= 1640973972444) && (ee.`timestamp` <= 1642701725804))
 18   idx_1714935113405431817   persistent   progress     false    false        99.98 %   [ `timestamp` ]                       ((ee.`timestamp` >= 1640973972444) && (ee.`timestamp` <= 1642701725804))
 18   idx_1714935113405431817   persistent   progress     false    false        99.98 %   [ `timestamp` ]                       ((ee.`timestamp` >= 1640973972444) && (ee.`timestamp` <= 1642701725804))
 18   idx_1714935113405431817   persistent   progress     false    false        99.98 %   [ `timestamp` ]                       ((ee.`timestamp` >= 1640973972444) && (ee.`timestamp` <= 1642701725804))
 18   idx_1714935113405431817   persistent   progress     false    false        99.98 %   [ `timestamp` ]                       ((ee.`timestamp` >= 1640973972444) && (ee.`timestamp` <= 1642701725804))
 18   idx_1714935113405431817   persistent   progress     false    false        99.98 %   [ `timestamp` ]                       ((ee.`timestamp` >= 1640973972444) && (ee.`timestamp` <= 1642701725804))
 18   idx_1714935113405431817   persistent   progress     false    false        99.98 %   [ `timestamp` ]                       ((ee.`timestamp` >= 1640973972444) && (ee.`timestamp` <= 1642701725804))
 18   idx_1714935113407528968   persistent   progress     false    false        18.20 %   [ `execPlanDetails.dataSourceUri` ]   (ee.`execPlanDetails`.`dataSourceUri` == null)
 18   idx_1714935113407528968   persistent   progress     false    false        18.20 %   [ `execPlanDetails.dataSourceUri` ]   (ee.`execPlanDetails`.`dataSourceUri` == null)
 18   idx_1714935113405431817   persistent   progress     false    false        99.98 %   [ `timestamp` ]                       ((ee.`timestamp` >= 1640973972444) && (ee.`timestamp` <= 1642701725804))
 18   idx_1714935113405431817   persistent   progress     false    false        99.98 %   [ `timestamp` ]                       ((ee.`timestamp` >= 1640973972444) && (ee.`timestamp` <= 1642701725804))
 18   idx_1714935113405431817   persistent   progress     false    false        99.98 %   [ `timestamp` ]                       ((ee.`timestamp` >= 1640973972444) && (ee.`timestamp` <= 1642701725804))
 18   idx_1714935113405431817   persistent   progress     false    false        99.98 %   [ `timestamp` ]                       ((ee.`timestamp` >= 1640973972444) && (ee.`timestamp` <= 1642701725804))
 18   idx_1714935113405431817   persistent   progress     false    false        99.98 %   [ `timestamp` ]                       ((ee.`timestamp` >= 1640973972444) && (ee.`timestamp` <= 1642701725804))
 18   idx_1714935113405431817   persistent   progress     false    false        99.98 %   [ `timestamp` ]                       ((ee.`timestamp` >= 1640973972444) && (ee.`timestamp` <= 1642701725804))
 18   idx_1714935113405431817   persistent   progress     false    false        99.98 %   [ `timestamp` ]                       ((ee.`timestamp` >= 1640973972444) && (ee.`timestamp` <= 1642701725804))
 18   idx_1714935113405431817   persistent   progress     false    false        99.98 %   [ `timestamp` ]                       ((ee.`timestamp` >= 1640973972444) && (ee.`timestamp` <= 1642701725804))
 18   idx_1714935113405431817   persistent   progress     false    false        99.98 %   [ `timestamp` ]                       ((ee.`timestamp` >= 1640973972444) && (ee.`timestamp` <= 1642701725804))
 18   idx_1714935113405431817   persistent   progress     false    false        99.98 %   [ `timestamp` ]                       ((ee.`timestamp` >= 1640973972444) && (ee.`timestamp` <= 1642701725804))
 18   idx_1714935113407528968   persistent   progress     false    false        18.20 %   [ `execPlanDetails.dataSourceUri` ]   (ee.`execPlanDetails`.`dataSourceUri` == null)
 18   idx_1714935113407528968   persistent   progress     false    false        18.20 %   [ `execPlanDetails.dataSourceUri` ]   (ee.`execPlanDetails`.`dataSourceUri` == null)
 18   idx_1714935113407528968   persistent   progress     false    false        18.20 %   [ `execPlanDetails.dataSourceUri` ]   (ee.`execPlanDetails`.`dataSourceUri` == null)
 18   idx_1714935113407528968   persistent   progress     false    false        18.20 %   [ `execPlanDetails.dataSourceUri` ]   (ee.`execPlanDetails`.`dataSourceUri` == null)
 18   idx_1714935113407528968   persistent   progress     false    false        18.20 %   [ `execPlanDetails.dataSourceUri` ]   (ee.`execPlanDetails`.`dataSourceUri` == null)
 18   idx_1714935113407528968   persistent   progress     false    false        18.20 %   [ `execPlanDetails.dataSourceUri` ]   (ee.`execPlanDetails`.`dataSourceUri` == null)
 18   idx_1714935113407528968   persistent   progress     false    false        18.20 %   [ `execPlanDetails.dataSourceUri` ]   (ee.`execPlanDetails`.`dataSourceUri` == null)
 18   idx_1714935113407528968   persistent   progress     false    false        18.20 %   [ `execPlanDetails.dataSourceUri` ]   (ee.`execPlanDetails`.`dataSourceUri` == null)
 18   idx_1714935113407528968   persistent   progress     false    false        18.20 %   [ `execPlanDetails.dataSourceUri` ]   (ee.`execPlanDetails`.`dataSourceUri` == null)
 18   idx_1714935113407528968   persistent   progress     false    false        18.20 %   [ `execPlanDetails.dataSourceUri` ]   (ee.`execPlanDetails`.`dataSourceUri` == null)
 18   idx_1714935113407528968   persistent   progress     false    false        18.20 %   [ `execPlanDetails.dataSourceUri` ]   (ee.`execPlanDetails`.`dataSourceUri` == null)
 18   idx_1714935113407528968   persistent   progress     false    false        18.20 %   [ `execPlanDetails.dataSourceUri` ]   (ee.`execPlanDetails`.`dataSourceUri` == null)
 18   idx_1714935113407528968   persistent   progress     false    false        18.20 %   [ `execPlanDetails.dataSourceUri` ]   (ee.`execPlanDetails`.`dataSourceUri` == null)
 18   idx_1714935113407528968   persistent   progress     false    false        18.20 %   [ `execPlanDetails.dataSourceUri` ]   (ee.`execPlanDetails`.`dataSourceUri` == null)
 18   idx_1714935113407528968   persistent   progress     false    false        18.20 %   [ `execPlanDetails.dataSourceUri` ]   (ee.`execPlanDetails`.`dataSourceUri` == null)
 18   idx_1714935113407528968   persistent   progress     false    false        18.20 %   [ `execPlanDetails.dataSourceUri` ]   (ee.`execPlanDetails`.`dataSourceUri` == null)
 18   idx_1714935113407528968   persistent   progress     false    false        18.20 %   [ `execPlanDetails.dataSourceUri` ]   (ee.`execPlanDetails`.`dataSourceUri` == null)
 18   idx_1714935113407528968   persistent   progress     false    false        18.20 %   [ `execPlanDetails.dataSourceUri` ]   (ee.`execPlanDetails`.`dataSourceUri` == null)
 18   idx_1714935113407528968   persistent   progress     false    false        18.20 %   [ `execPlanDetails.dataSourceUri` ]   (ee.`execPlanDetails`.`dataSourceUri` == null)
 18   idx_1714935113407528968   persistent   progress     false    false        18.20 %   [ `execPlanDetails.dataSourceUri` ]   (ee.`execPlanDetails`.`dataSourceUri` == null)

Optimization rules applied:
 Id   RuleName
  1   move-calculations-up
  2   move-filters-up
  3   move-calculations-up-2
  4   move-filters-up-2
  5   use-indexes
  6   move-calculations-down
  7   fuse-filters
  8   scatter-in-cluster
  9   distribute-filtercalc-to-cluster
 10   distribute-sort-to-cluster
 11   remove-unnecessary-remote-scatter
 12   sort-limit
 13   reduce-extraction-to-projection
 14   decay-unnecessary-sorted-gather

Query Statistics:
 Writes Exec   Writes Ign   Scan Full   Scan Index   Filtered   Exec Time [s]
           0            0           0       138932          0        26.99118

Query Profile:
 Query Stage           Duration [s]
 initializing               0.00000
 parsing                    0.00015
 optimizing ast             0.00002
 loading collections        0.00000
 instantiating plan         0.00004
 optimizing plan            0.00399
 executing                 26.97818
 finalizing                 0.00879

Query to fetch datasource fails with AsyncTimeout exception in spline but takes around 250s when fired directly in Arango

Time taken by spline to retrieve results

Arango Query Profile

Query String (1104 chars, cacheable: false):
 WITH progress, progressOf, executionPlan, affects, dataSource
 FOR ds IN dataSource
     FILTER ds._created <= 1642702559425
     
     // last write event or null
     LET lwe = FIRST(
         FOR we IN 2
             INBOUND ds affects, progressOf
             FILTER we.timestamp >= 1642702559425
                AND we.timestamp <= 1642701725804
             SORT we.timestamp DESC
             RETURN we
     )
     FILTER NOT IS_NULL(lwe)
     LET resItem = {
         "executionEventId" : lwe._key,
         "executionPlanId"  : lwe.execPlanDetails.executionPlanKey,
         "frameworkName"    : lwe.execPlanDetails.frameworkName,
         "applicationName"  : lwe.execPlanDetails.applicationName,
         "applicationId"    : lwe.extra.appId,
         "timestamp"        : lwe.timestamp || 0,
         "dataSourceName"   : REGEX_MATCHES(ds.uri, "([^/]+)/*$")[1],
         "dataSourceUri"    : ds.uri,
         "dataSourceType"   : lwe.execPlanDetails.dataSourceType,
         "append"           : lwe.execPlanDeta...

Execution plan:
 Id   NodeType                  Site  Calls    Items   Runtime [s]   Comment
  1   SingletonNode             DBS       1        1       0.00001   * ROOT
  2   EnumerateCollectionNode   DBS     129   128241       0.11741     - FOR ds IN dataSource   /* full collection scan, 1 shard(s) */   FILTER (ds.`_created` <= 1642702559425)   /* early pruning */
 24   RemoteNode                COOR    258   128241       0.43033       - REMOTE
 25   GatherNode                COOR    258   128241       0.05706       - GATHER   /* unsorted */
 26   SubqueryStartNode         COOR    386   256482       0.15042       - LET #2 = ( /* subquery begin */
  6   TraversalNode             COOR    524   394967     250.77225         - FOR we  /* vertex */ IN 2..2  /* min..maxPathDepth */ INBOUND ds /* startnode */  affects, INBOUND progressOf
  7   CalculationNode           COOR    524   394967       0.13238           - LET #10 = ((we.`timestamp` >= 1642702559425) && (we.`timestamp` <= 1642701725804))   /* simple expression */
  8   FilterNode                COOR    258   128241       0.07487           - FILTER #10
  9   CalculationNode           COOR    258   128241       0.02593           - LET #12 = we.`timestamp`   /* attribute expression */
 10   SortNode                  COOR    258   128241       0.09009           - SORT #12 DESC   /* sorting strategy: constrained heap */
 21   LimitNode                 COOR    258   128241       0.00674           - LIMIT 0, 1
 27   SubqueryEndNode           COOR    258   128241       0.03921           - RETURN  we ) /* subquery end */
 13   CalculationNode           COOR    258   128241       0.01077       - LET lwe = FIRST(#2)   /* simple expression */
 14   CalculationNode           COOR    258   128241       0.01014       - LET #14 = (lwe != null)   /* simple expression */
 15   FilterNode                COOR    130        0       0.00183       - FILTER #14
 17   CalculationNode           COOR    130        0       0.00000       - LET #16 = REGEX_MATCHES(ds.`uri`, "([^/]+)/*$")[1]   /* simple expression */   /* collections used: ds : dataSource */
 18   SortNode                  COOR    130        0       0.00000       - SORT #16 ASC   /* sorting strategy: constrained heap */
 16   CalculationNode           COOR    130        0       0.00000       - LET resItem = { "executionEventId" : lwe.`_key`, "executionPlanId" : lwe.`execPlanDetails`.`executionPlanKey`, "frameworkName" : lwe.`execPlanDetails`.`frameworkName`, "applicationName" : lwe.`execPlanDetails`.`applicationName`, "applicationId" : lwe.`extra`.`appId`, "timestamp" : (lwe.`timestamp` || 0), "dataSourceName" : REGEX_MATCHES(ds.`uri`, "([^/]+)/*$")[1], "dataSourceUri" : ds.`uri`, "dataSourceType" : lwe.`execPlanDetails`.`dataSourceType`, "append" : (lwe.`execPlanDetails`.`append` || false) }   /* simple expression */   /* collections used: ds : dataSource */
 19   LimitNode                 COOR    130        0       0.00000       - LIMIT 10, 10
 20   ReturnNode                COOR    130        0       0.00001       - RETURN resItem

Indexes used:
 By   Name   Type   Collection   Unique   Sparse   Selectivity   Fields      Ranges
  6   edge   edge   affects      false    false        21.03 %   [ `_to` ]   base INBOUND
  6   edge   edge   progressOf   false    false        99.98 %   [ `_to` ]   base INBOUND

Traversals on graphs:
 Id  Depth  Vertex collections  Edge collections     Options                                  Filter / Prune Conditions
 6   2..2                       affects, progressOf  uniqueVertices: none, uniqueEdges: path                           

Optimization rules applied:
 Id   RuleName
  1   simplify-conditions
  2   move-calculations-up
  3   move-filters-up
  4   optimize-subqueries
  5   move-calculations-up-2
  6   move-filters-up-2
  7   move-calculations-down
  8   scatter-in-cluster
  9   distribute-filtercalc-to-cluster
 10   remove-unnecessary-remote-scatter
 11   sort-limit
 12   move-filters-into-enumerate
 13   splice-subqueries

Query Statistics:
 Writes Exec   Writes Ign   Scan Full   Scan Index   Filtered   Exec Time [s]
           0            0      128431       537792     395157       251.92503

Query Profile:
 Query Stage           Duration [s]
 initializing               0.00000
 parsing                    0.00017
 optimizing ast             0.00002
 loading collections        0.00001
 instantiating plan         0.00007
 optimizing plan            0.00433
 executing                251.91947
 finalizing                 0.00095

[abhishekshenoy]

This helped me understand the issue

#932

#940

[wajda]

There is more to this - #1000 and #1001
We are working on it