5 Replies Latest reply on Mar 5, 2019 2:26 PM by mohanr.k

    Find time taken by PGQL query using Cytoscape

    mohanr.k

      Is it possible to get pgql query metrics like start time, end time, time taken by query to return results etc... when we run pgql query from cytoscape? If so please share the details.

       

      Oracle : 18c

      PGX version: 3.1.0

      Cytoscape version: 3.6.1

        • 1. Re: Find time taken by PGQL query using Cytoscape
          Gianni Ceresa

          I don't remember seeing something like that inside Cytoscape.

          As a workaround you could get an approximation by enabling more detailed logging on the PGX server side and comparing timestamps between various logs messages.

          PGX is very talkative when pushing the log level (it has lot of trace and debug messages), but the amount of logs generated will be huge (just with creating a session, loading a graph with 4 nodes (3 properties) and 4 edges (no properties) and destroying both the graph and the session I got a file of 400Kb of logs when enabling logs for all the levels.

          Of course this is just a workaround to get some timings.

          I would probably use a different approach to have a more precise timing (also because I believe the query itself could be quite fast and there is lot of time spent in other activities. In Cytoscape for example the tool is quite slow in adding a node and a edge on screen. If the graph visualization is closed things are faster, if it's visible it get slower and slower with more objects you load.

          • 2. Re: Find time taken by PGQL query using Cytoscape
            mohanr.k

            Do you have any recommendations on how to achieve this?

            • 3. Re: Find time taken by PGQL query using Cytoscape
              Gianni Ceresa

              If it's purely for testing, having an idea of how long a query take, you could probably get a better idea by using the PGX shell. It gives you access to lot of Java functions and you could implement that kind of solution: https://stackoverflow.com/questions/180158/how-do-i-time-a-methods-execution-in-java

              If you replace the 'methodToTime()' by the resultSet = your-graph.queryPgql("your query").

              It's still quite approximative (doing copy/paste of the whole block of code you would remove the "writing" time of the code.

               

              It's still a quite empirical method, using other languages like python or java to execute the query would probably give you something a bit more controlled and reproductible.

               

              Just now thinking at the topic I would exclude that PGX logging would already have the metric somewhere, would need to try once to see what it return and if something nice is available.

              Will give it a try and I tell you if I find you something nice there inside.

              • 4. Re: Find time taken by PGQL query using Cytoscape
                Gianni Ceresa

                Here is what I got in logging when enabling everything and only executing a PGQL query:

                 

                2019-03-01 21:53:04.946 [http-nio-7007-exec-4] DEBUG oracle.pgx.rest.filter.CsrfTokenValidator - received content type application/json; charset=UTF-8
                2019-03-01 21:53:04.952 [http-nio-7007-exec-4] INFO  oracle.pgx.rest.endpoints.PgqlResource - Querying graph test01 with 'SELECT n1, e, n2 WHERE (n1) -[e]-> (n2)' under HOMOMORPHISM semantic, true schema strictness
                2019-03-01 21:53:04.954 [http-nio-7007-exec-4] DEBUG oracle.pgx.engine.Server - enqueue task EXTRACT_PGQL_GRAPH_NAMES
                2019-03-01 21:53:04.954 [pgx-server-main-thread-0] TRACE oracle.pgx.api.internal.characteristic.WorkloadCharacteristicTranslation - Cache miss for WorkloadCharacteristicSet{[IO_BOUND, READ_ONLY, SEQUENTIAL]}
                2019-03-01 21:53:04.955 [pgx-server-main-thread-0] TRACE oracle.pgx.api.internal.characteristic.WorkloadCharacteristicTranslation - Matching WorkloadCharacteristicSet{[IO_BOUND, READ_ONLY, SEQUENTIAL]} against predicate IO_BOUND
                2019-03-01 21:53:04.955 [pgx-server-main-thread-0] DEBUG oracle.pgx.engine.exec.Task - submit EXTRACT_PGQL_GRAPH_NAMES to io-pool
                2019-03-01 21:53:04.964 [pgx-io-pool-worker-5] DEBUG oracle.pgx.engine.exec.Task - 7494a455-b7dc-4120-b51a-9d09b7181141 START ====> EXTRACT_PGQL_GRAPH_NAMES
                2019-03-01 21:53:04.964 [pgx-io-pool-worker-5] DEBUG oracle.pgx.engine.exec.Task - task EXTRACT_PGQL_GRAPH_NAMES acquires READ_ONLY lock for session
                2019-03-01 21:53:04.967 [pgx-io-pool-worker-5] DEBUG oracle.pgx.engine.pgql.PgqlQueryManagerImpl - Query not found in cache. Compiling it now.
                2019-03-01 21:53:04.971 [pgx-io-pool-worker-5] TRACE org.metaborg.spoofax.core.syntax.JSGLRParseService - Parsing ram:///pgql/3b7dfdf3-8d6f-4d87-8ba0-71e7b57909d4.pgql
                2019-03-01 21:53:04.997 [pgx-io-pool-worker-5] TRACE org.metaborg.spoofax.core.analysis.taskengine.TaskEngineAnalyzer - Invoking editor-analyze strategy
                2019-03-01 21:53:05.043 [pgx-io-pool-worker-5] DEBUG oracle.pgx.engine.exec.Task - task EXTRACT_PGQL_GRAPH_NAMES unlocks (READ_ONLY) session
                2019-03-01 21:53:05.043 [pgx-io-pool-worker-5] DEBUG oracle.pgx.engine.exec.Task - 7494a455-b7dc-4120-b51a-9d09b7181141 FINISHED => EXTRACT_PGQL_GRAPH_NAMES: total task exec time = 79 ms (0 secs)
                2019-03-01 21:53:05.045 [pgx-io-pool-worker-5] DEBUG oracle.pgx.engine.Server - start caller thread task COLLECT_IN_PLACE_UPDATE_GRAPHS
                2019-03-01 21:53:05.045 [pgx-io-pool-worker-5] DEBUG oracle.pgx.engine.exec.Task - 7494a455-b7dc-4120-b51a-9d09b7181141 START ====> COLLECT_IN_PLACE_UPDATE_GRAPHS
                2019-03-01 21:53:05.045 [pgx-io-pool-worker-5] DEBUG oracle.pgx.engine.exec.Task - task COLLECT_IN_PLACE_UPDATE_GRAPHS acquires READ_ONLY lock for session
                2019-03-01 21:53:05.046 [pgx-io-pool-worker-5] DEBUG oracle.pgx.engine.refresh.GraphTaskLocking - Graphs with inplace-update: []
                2019-03-01 21:53:05.046 [pgx-io-pool-worker-5] DEBUG oracle.pgx.engine.exec.Task - task COLLECT_IN_PLACE_UPDATE_GRAPHS unlocks (READ_ONLY) session
                2019-03-01 21:53:05.046 [pgx-io-pool-worker-5] DEBUG oracle.pgx.engine.exec.Task - 7494a455-b7dc-4120-b51a-9d09b7181141 FINISHED => COLLECT_IN_PLACE_UPDATE_GRAPHS: total task exec time = 1 ms (0 secs)
                2019-03-01 21:53:05.047 [pgx-io-pool-worker-5] DEBUG oracle.pgx.engine.Server - enqueue task QUERY_PGQL
                2019-03-01 21:53:05.047 [pgx-server-main-thread-0] DEBUG oracle.pgx.engine.exec.Task - submit QUERY_PGQL to analysis-pool
                2019-03-01 21:53:05.049 [pgx-analysis-pool-worker-5] DEBUG oracle.pgx.engine.exec.Task - 7494a455-b7dc-4120-b51a-9d09b7181141 START ====> QUERY_PGQL
                2019-03-01 21:53:05.049 [pgx-analysis-pool-worker-5] DEBUG oracle.pgx.engine.exec.Task - task QUERY_PGQL acquires READ_WRITE lock for session
                2019-03-01 21:53:05.049 [pgx-analysis-pool-worker-5] DEBUG oracle.pgx.engine.pgql.PgqlQueryManagerImpl - 7494a455-b7dc-4120-b51a-9d09b7181141, run a PGQL query "SELECT n1, e, n2 WHERE (n1) -[e]-> (n2)" START
                2019-03-01 21:53:05.063 [pgx-analysis-pool-worker-5] DEBUG oracle.pgx.engine.pgql.PgqlQueryManagerImpl - matching semantic is homomorphism
                2019-03-01 21:53:05.063 [pgx-analysis-pool-worker-5] DEBUG oracle.pgx.engine.pgql.PgqlQueryManagerImpl - query:
                
                
                SELECT n1, e, n2
                MATCH (n1) -[e]-> (n2)
                
                
                2019-03-01 21:53:05.085 [pgx-analysis-pool-worker-5] DEBUG oracle.pgx.engine.pgql.PgqlQueryManagerImpl - plan:
                
                
                \--- (n1) -[e]-> (n2) NeighborMatch {"cardinality":"4", "cost":"4", "accumulatedCost":"8"}
                     \--- (n1) RootVertexMatch {"cardinality":"4", "cost":"4", "accumulatedCost":"4"}
                
                
                2019-03-01 21:53:05.142 [pgx-analysis-pool-worker-5] TRACE oracle.pgx.runtime.util.allocation.MemoryAllocator - Allocating 524288 bytes (init-to-0: false)
                2019-03-01 21:53:05.142 [pgx-analysis-pool-worker-5] TRACE oracle.pgx.runtime.util.allocation.MemoryAllocator - Allocated 524288 bytes (0 MBs). Total off-heap size: 0 MBs (0.0 GBs)
                2019-03-01 21:53:05.152 [pgx-analysis-pool-worker-5] TRACE oracle.pgx.runtime.util.allocation.MemoryAllocator - Allocating 1048576 bytes (init-to-0: false)
                2019-03-01 21:53:05.152 [pgx-analysis-pool-worker-5] TRACE oracle.pgx.runtime.util.allocation.MemoryAllocator - Allocated 1048576 bytes (1 MBs). Total off-heap size: 1 MBs (9.765625E-4 GBs)
                2019-03-01 21:53:05.152 [pgx-analysis-pool-worker-5] TRACE oracle.pgx.runtime.util.allocation.MemoryAllocator - Allocating 1048576 bytes (init-to-0: false)
                2019-03-01 21:53:05.152 [pgx-analysis-pool-worker-5] TRACE oracle.pgx.runtime.util.allocation.MemoryAllocator - Allocated 1048576 bytes (1 MBs). Total off-heap size: 2 MBs (0.001953125 GBs)
                2019-03-01 21:53:05.153 [pgx-analysis-pool-worker-5] TRACE oracle.pgx.runtime.util.allocation.MemoryAllocator - Freed 524288 bytes (0 MBs). Total off-heap size: 2 MBs (0.001953125 GBs)
                2019-03-01 21:53:05.168 [pgx-analysis-pool-worker-5] DEBUG oracle.pgx.engine.pgql.PgqlQueryManagerImpl - 7494a455-b7dc-4120-b51a-9d09b7181141, run a PGQL query "SELECT n1, e, n2 WHERE (n1) -[e]-> (n2)" (pgql_1) FINISHED
                2019-03-01 21:53:05.168 [pgx-analysis-pool-worker-5] DEBUG oracle.pgx.engine.exec.Task - task QUERY_PGQL unlocks (READ_WRITE) session
                2019-03-01 21:53:05.168 [pgx-analysis-pool-worker-5] DEBUG oracle.pgx.engine.exec.Task - 7494a455-b7dc-4120-b51a-9d09b7181141 FINISHED => QUERY_PGQL: total task exec time = 119 ms (0 secs)
                

                 

                As you can see there are some metrics about memory usage and time spent.

                The last line is probably what you would be looking for: FINISHED => QUERY_PGQL: total task exec time = 119 ms (0 secs)

                • 5. Re: Find time taken by PGQL query using Cytoscape
                  mohanr.k

                  Thank you. I saw some option in PGX shell. I will try that