Full Description of Query Log Entry

Suresh Ramagiri -

Each query log entry is made up of the following bits of information:

[timestamp] [nodename] [process name] [category] [SID] [db] [user] [ac] [xid] [sql] [status] [execution time] [reads] [inserts] [deletes] [updates] [counts] [rows_read] [forwards] [broadcasts] [rows_output] [semaphore_matches] [fragment_executions] [runtime_ns] [cpu_waits] [cpu_waittime_ns] [bm_fixes] [bm_loads] [bm_waittime_ns] [lockman_waits] [lockman_waittime_ms] [trxstate_waits] [trxstate_waittime_ms] [wal_perm_waittime_ms] [bm_perm_waittime_ms] [sigmas] [sigma_fallbacks] [row_count] [found_rows] [insert_id] [fanout] [attempts]

  • timestamp: Includes the timezone. It is extremely important to have the clocks in sync on all the nodes.
  • nodename: Name of the node where the entry was logged.
  • process name: The Clustrix process name, "clxnode". Will be "real" on the legacy appliance.
  • category: Type of entry in the log. SLOW, DDL, BAD or SQLERR.
  • sid: session ID. Useful when trying to identify a particular session with the queries that were logged.
  • db: database name the query was run from.
  • user: User executing the query. If you're using statement-based replication, you may want to search for the replication account when troubleshooting statements from the master.
  • ac: auto-commit. This is useful to determine whether the query was in an explicit transaction. Note that DDLs will all have ac=N even if the DDLs are not in an explicit transaction.
  • xid: transaction ID. Useful to link a session to an XID when troubleshooting locking issues.
  • sql: full query, unless the query exceeds the 4KB statement buffer; the logger will then insert ellipses in the middle of the query and remove part of the query to fit the 4KB limit.
  • status: The result of the query like rows affected or error message.
  • time: total time from when the query was received, compiled, processed and output returned. This is what we look at for SLOW queries.
  • reads: Number of calls by the query execution engine to operators CONTAINER_READ and CONTAINER_MULTI_READ. The number of times the database reads from a container (but not the number of rows read).
  • inserts: Number of calls by the query execution engine to operators CONTAINER_INSERT and CONTAINER_INSREP. The number of times the database inserts to a container. This includes both the number of calls, and the number of rows written.
  • deletes: Number of calls by the query execution engine to operator CONTAINER_REMOVE. The number of times the database deletes from a container. This includes both the number of calls, and the number of rows deleted.
  • updates: Number of calls by the query execution engine to operators CONTAINER_UPDATE and CONTAINER_OVERWRITE. The number of times the database updates a container. This includes both the number of calls, and the number of rows updated.
  • counts: Number of calls by the query execution engine to operators BARRIER_ADD and BARRIER_FETCHADD.
  • rows_read: Rows read by the query execution engine from operators CONTAINER_READ, CONTAINER_MULTI_READ, and MERGE_SORT_READ. The Total number of rows read to get all needed data for the query, includes reads from indexes.
  • forwards: Number of rows forwarded to specific nodes.
  • broadcasts: Number of rows broadcast to all nodes.
  • rows_output: Number of calls by the query execution engine to operator OUTPUT_START. The Total number of rows returned.
  • semaphore_matches: Number of calls by the query execution engine to operator SEM_ACQUIRE.
  • runtime_ns: Nanoseconds the database spent executing bytecode. This represents the aggregate total CPU time spent by all nodes to run the query.
  • cpu_wait: Amount of time spent waiting on the CPU
  • cpu_waittime_ns:  Nanoseconds that CPU spent executing query
  • bm_fixes: Number of attempted page fixes by the Buffer Manager.
  • bm_loads: Number of pages loaded from disk by the Buffer Manager.
  • bm_waittime_ns: Nanoseconds spent blocked on Buffer Manager page fixes.
  • lockman_waits: Number of calls by the query execution engine to operators LOCK_SHARED and LOCK_EXCLUSIVE that had to block. The number of times that the query had to wait for a lock to be released by another query.
  • lockman_waittime_ms: Milliseconds spent blocked during VM operators LOCK_SHARED and LOCK_EXCLUSIVE. The total time spent waiting for other queries to release locks on needed rows.
  • trxstate_waits: Number of calls to trxstate_check that had to block.
  • trxstate_waittime_ms: Milliseconds spent blocked in trxstate_check.
  • wal_perm_waittime_ms: Milliseconds spent blocked in WALS waiting for the checkpoint, because WAL was too full.
  • bm_perm_waittime_ms: Milliseconds spent waiting for the Buffer Manager to grant write permission for pages.
  • sigmas: Count of sigma containers used by the query. Sigmas are used to store intermediate and/or result rows for some queries.
  • sigma_fallbacks: Number of sigmas that did not fit in memory and had to fall back to disk.
  • row_count: Rows affected by the query
  • found_rows: Rows returned by the query
  • fanout: Indicates whether fanout was used by the query.
  • attempts: Indicates how many times this query was attempted.

New in 8.x. The following will only show when they are greater than 0ms:

  • translate: time spent in translate_dml()
  • prefetch: time spent building the sierra stub (includes fetching pds)
  • plan: time spent in normalize/plan
  • compile: time spent in compiling sierra to til
  • execution: time spent in invocation

 

Have more questions? Submit a request

0 Comments

Please sign in to leave a comment.
Powered by Zendesk