Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

sql: cluster performance degrades after adding and dropping hundreds of tables #20753

Closed
lgo opened this issue Dec 15, 2017 · 18 comments
Closed
Assignees
Labels
A-schema-descriptors Relating to SQL table/db descriptor handling. C-performance Perf of queries or internals. Solution not expected to change functional behavior.
Milestone

Comments

@lgo
Copy link
Contributor

lgo commented Dec 15, 2017

While running Ruby's ActiveRecord test suite, each test file will drop and add 185 tables.

After running the tests for awhile, the amount of replicas grows to several thousand and the tests become extremely slow. As the replica count increases so did the 99th percentile latency.

From measurements of running the same test continuously, it would take around 2s total while running against a fresh database. The 99th percentile latency was about 20ms. That time would increase and would reach a point where the file would consistently take at least 10s to run, and often 20s-30s. The 99th percentile then would be over 200ms.

Something to note is that dropping and re-creating the database did not help with performance, or reduce the replicas. The only way to bring the latency back down was to completely delete the database files.

These were the graphs of the database while running it. Mind the break in activity as there was a period where no tests were being run.

screen shot 2017-12-14 at 3 34 59 pm

@lgo lgo added the C-performance Perf of queries or internals. Solution not expected to change functional behavior. label Dec 15, 2017
@petermattis
Copy link
Collaborator

We've run clusters with tens of thousands of replicas and not seen significant performance degradation due to the number of replicas. Can you show the graph of "quiescent" replicas? As long as most of the replicas are quiescent, the number doesn't matter too much. (That's not completely true, quiescent replicas still consume a very tiny amount of cpu). Regardless of whether it is the number of replicas or something else, this deserves investigating.

Assigning to @nvanbenschoten for triage.

@nvanbenschoten
Copy link
Member

nvanbenschoten commented Dec 15, 2017

Thanks for filing @LEGO. @petermattis I'll take this one myself.

@lgo
Copy link
Contributor Author

lgo commented Dec 15, 2017

Got it. All the replicas do become quiescent. Nothing else stands out about the graphs, just that SQL latency climbs and KV latency climbs (but far less, 5ms starting to 10ms during bad performance)

I'm going to give a shot at running these tests on VMs and a cluster, as it might be other factors at play. I did think it may be the fact of running it locally but if the tests once when there is no other activity going on, CockroachDB doesn't increase much in CPU or memory usage but still has trouble.

For reference, here are all the queries executed. It's quite noisy, I'll try to narrow down some of the problems. There are 2 files, one for the queries that create the data, and one that runs test cases. It appears that they both run twice, also. The second set of queries start running a bit before the first session finishes.

railstests_queries.1.log
railstests_queries.2.log

@lgo
Copy link
Contributor Author

lgo commented Dec 16, 2017

So I created a short Go program to record the elapsed time for 5 different queries:

  1. Drop table if exists.
  2. Create table. The schema is just id int
  3. Run an introspection query. These queries are very frequent in the rails tests while populating fixtures.
SELECT t2.oid::REGCLASS::TEXT AS to_table, a1.attname AS column, a2.attname AS primary_key, c.conname AS name, c.confupdtype AS on_update, c.confdeltype AS on_delete FROM pg_constraint AS c JOIN pg_class AS t1 ON c.conrelid = t1.oid JOIN pg_class AS t2 ON c.confrelid = t2.oid JOIN pg_attribute AS a1 ON (a1.attnum = c.conkey[1]) AND (a1.attrelid = t1.oid) JOIN pg_attribute AS a2 ON (a2.attnum = c.confkey[1]) AND (a2.attrelid = t2.oid) JOIN pg_namespace AS t3 ON c.connamespace = t3.oid WHERE ((c.contype = 'f') AND (t1.relname = <TABLENAME>)) AND (t3.nspname = ANY (current_schemas(false))) ORDER BY c.conname
  1. Insert a row.
  2. Query for the row.

Here's a rolling average of each of the queries. The latency increase is related to the dropped tables and only applies to the drop table and introspective query. Create table has a marginal increase in latency. I haven't modified GC time yet in my tests.

figure_2-1

(the code for benchmarking and plotting can be found in this gist)

A quick guess is that getting all of the descriptors and/or iterating over them could be slow for the introspective query in pg_class. Nothing obviously bad is happening in drop table so I'll need to investigate more. This could just have to do with descriptors not being removed yet and then some inefficient parts.

@nvanbenschoten
Copy link
Member

@LEGO nice investigation! Have you played around at all with request tracing (see here and here)? I'd expect you'd get some insight out of comparing a trace from before and after the introspection query gets slow.

@nvanbenschoten
Copy link
Member

@LEGO let me know if you're planning on continuing this investigation. If not, I'd be happy to take it over.

@lgo
Copy link
Contributor Author

lgo commented Dec 21, 2017

I discussed things a bit more with @nvanbenschoten but didn't get to fully investigate this.

This is the trace for the (rather long, joining) introspection query.

+----------------------------------+----------------+------------------------------------------------+-----------------------------------+-----------------------------+------------------+-------+
|            timestamp             |      age       |                    message                     |                tag                |             loc             |    operation     | span  |
+----------------------------------+----------------+------------------------------------------------+-----------------------------------+-----------------------------+------------------+-------+
| 2017-12-18 14:49:16.797177+00:00 | 0s             | === SPAN START: sql txn implicit ===           |                                   |                             | sql txn implicit | (0,0) |
| 2017-12-18 14:49:16.849478+00:00 | 52ms300µs891ns | === SPAN START: starting plan ===              |                                   |                             | starting plan    | (0,1) |
| 2017-12-18 14:49:16.849605+00:00 | 52ms428µs767ns | txn: bytes usage increases to 1.0 MiB (+30720) | [client=[::1]:56725,user=root,n1] | util/mon/bytes_usage.go:548 | starting plan    | (0,1) |
| 2017-12-18 14:49:16.850189+00:00 | 53ms12µs820ns  | === SPAN START: consuming rows ===             |                                   |                             | consuming rows   | (0,2) |
| 2017-12-18 14:49:16.850198+00:00 | 53ms21µs601ns  | plan completed execution                       | [client=[::1]:56725,user=root,n1] |                             | consuming rows   | (0,2) |
| 2017-12-18 14:49:16.850205+00:00 | 53ms28µs255ns  | resources released, stopping trace             | [client=[::1]:56725,user=root,n1] |                             | consuming rows   | (0,2) |
+----------------------------------+----------------+------------------------------------------------+-----------------------------------+-----------------------------+------------------+-------+
(6 rows)

Time: 54.433837ms

This is the trace for the DROP TABLE.

root@:26257/test> set tracing=on;
SET

Time: 298.504µs

root@:26257/test> drop table ramaz;
DROP TABLE

Time: 62.85619ms

root@:26257/test> set tracing=off;
SET

Time: 279.921µs

root@:26257/test> select * from cockroachdb_internal.session_trace;
pq: database "cockroachdb_internal" does not exist
root@:26257/test> select * from crdb_internal.session_trace;
+---------+----------+-------------+----------------------------------+----------------+-------------------------------------------+----------------------+-------------------------------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| txn_idx | span_idx | message_idx |            timestamp             |    duration    |                 operation                 |         loc          |                 tag                 |                                                                                                                       message                                                                                                                        |
+---------+----------+-------------+----------------------------------+----------------+-------------------------------------------+----------------------+-------------------------------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
|       0 |        0 |           0 | 2017-12-21 23:01:20.518382+00:00 | 133µs929ns     | sql txn implicit                          |                      |                                     | === SPAN START: sql txn implicit ===                                                                                                                                                                                                                 |
|       0 |        0 |           1 | 2017-12-21 23:01:20.518513+00:00 | NULL           | NULL                                      |                      | [client=[::1]:54702,user=root,n1]   | AutoCommit. err: <nil>␤                                                                                                                                                                                                                              |
|         |          |             |                                  |                |                                           |                      |                                     | txn: "sql txn implicit" id=f909297f key=/Min rw=false pri=0.02074726 iso=SERIALIZABLE stat=COMMITTED epo=0 ts=1513897280.518392330,0 orig=1513897280.518392330,0 max=1513897281.018392330,0 wto=false rop=false seq=1                                |
|       1 |        0 |           0 | 2017-12-21 23:01:20.518624+00:00 | 78µs907ns      | sql txn implicit                          |                      |                                     | === SPAN START: sql txn implicit ===                                                                                                                                                                                                                 |
|       1 |        0 |           1 | 2017-12-21 23:01:20.518656+00:00 | NULL           | NULL                                      |                      | [client=[::1]:54702,user=root,n1]   | executing 1/1: SHOW TRANSACTION STATUS                                                                                                                                                                                                               |
|       1 |        0 |           2 | 2017-12-21 23:01:20.5187+00:00   | NULL           | NULL                                      |                      | [client=[::1]:54702,user=root,n1]   | AutoCommit. err: <nil>␤                                                                                                                                                                                                                              |
|         |          |             |                                  |                |                                           |                      |                                     | txn: "sql txn implicit" id=1c6b76da key=/Min rw=false pri=0.00544139 iso=SERIALIZABLE stat=COMMITTED epo=0 ts=1513897280.518643049,0 orig=1513897280.518643049,0 max=1513897281.018643049,0 wto=false rop=false seq=1                                |
|       2 |        0 |           0 | 2017-12-21 23:01:20.518778+00:00 | 211µs175ns     | sql txn implicit                          |                      |                                     | === SPAN START: sql txn implicit ===                                                                                                                                                                                                                 |
|       2 |        0 |           1 | 2017-12-21 23:01:20.518791+00:00 | NULL           | NULL                                      |                      | [client=[::1]:54702,user=root,n1]   | executing 1/1: SHOW database                                                                                                                                                                                                                         |
|       2 |        0 |           2 | 2017-12-21 23:01:20.518942+00:00 | NULL           | NULL                                      |                      | [client=[::1]:54702,user=root,n1]   | query not supported for distSQL: unsupported node *sql.valuesNode without SQL VALUES clause                                                                                                                                                          |
|       2 |        0 |           3 | 2017-12-21 23:01:20.518986+00:00 | NULL           | NULL                                      |                      | [client=[::1]:54702,user=root,n1]   | AutoCommit. err: <nil>␤                                                                                                                                                                                                                              |
|         |          |             |                                  |                |                                           |                      |                                     | txn: "sql txn implicit" id=f7de4a78 key=/Min rw=false pri=0.04411871 iso=SERIALIZABLE stat=COMMITTED epo=0 ts=1513897280.518782862,0 orig=1513897280.518782862,0 max=1513897281.018782862,0 wto=false rop=false seq=1                                |
|       3 |        0 |           0 | 2017-12-21 23:01:28.286035+00:00 | 11ms113µs316ns | sql txn implicit                          |                      |                                     | === SPAN START: sql txn implicit ===                                                                                                                                                                                                                 |
|       3 |        0 |           1 | 2017-12-21 23:01:28.286067+00:00 | NULL           | NULL                                      |                      | [client=[::1]:54702,user=root,n1]   | executing 1/1: DROP TABLE ramaz                                                                                                                                                                                                                      |
|       3 |        0 |           2 | 2017-12-21 23:01:28.286144+00:00 | NULL           | NULL                                      |                      | [client=[::1]:54702,user=root,n1]   | querying next range at /Table/2/1/0/"test"/3/1                                                                                                                                                                                                       |
|       3 |        0 |           3 | 2017-12-21 23:01:28.286174+00:00 | NULL           | NULL                                      |                      | [client=[::1]:54702,user=root,n1]   | r7: sending batch 1 Get to (n1,s1):1                                                                                                                                                                                                                 |
|       3 |        0 |           4 | 2017-12-21 23:01:28.286176+00:00 | NULL           | NULL                                      |                      | [client=[::1]:54702,user=root,n1]   | sending request to local server                                                                                                                                                                                                                      |
|       3 |        1 |           0 | 2017-12-21 23:01:28.286239+00:00 | 119µs489ns     | /cockroach.roachpb.Internal/Batch         |                      |                                     | === SPAN START: /cockroach.roachpb.Internal/Batch ===                                                                                                                                                                                                |
|       3 |        1 |           1 | 2017-12-21 23:01:28.286245+00:00 | NULL           | NULL                                      |                      | [n1]                                | 1 Get                                                                                                                                                                                                                                                |
|       3 |        1 |           2 | 2017-12-21 23:01:28.286249+00:00 | NULL           | NULL                                      |                      | [n1]                                | read has no clock uncertainty                                                                                                                                                                                                                        |
|       3 |        1 |           3 | 2017-12-21 23:01:28.286254+00:00 | NULL           | NULL                                      |                      | [n1,s1]                             | executing 1 requests                                                                                                                                                                                                                                 |
|       3 |        1 |           4 | 2017-12-21 23:01:28.286262+00:00 | NULL           | NULL                                      |                      | [n1,s1,r7/1:/Table/{SystemCon…-11}] | read-only path                                                                                                                                                                                                                                       |
|       3 |        1 |           5 | 2017-12-21 23:01:28.28627+00:00  | NULL           | NULL                                      |                      | [n1,s1,r7/1:/Table/{SystemCon…-11}] | command queue                                                                                                                                                                                                                                        |
|       3 |        1 |           6 | 2017-12-21 23:01:28.286279+00:00 | NULL           | NULL                                      |                      | [n1,s1,r7/1:/Table/{SystemCon…-11}] | waiting for read lock                                                                                                                                                                                                                                |
|       3 |        1 |           7 | 2017-12-21 23:01:28.286343+00:00 | NULL           | NULL                                      |                      | [n1,s1,r7/1:/Table/{SystemCon…-11}] | read completed                                                                                                                                                                                                                                       |
|       3 |        0 |           5 | 2017-12-21 23:01:28.286385+00:00 | NULL           | NULL                                      |                      | [client=[::1]:54702,user=root,n1]   | querying next range at /Table/3/1/50/2/1                                                                                                                                                                                                             |
|       3 |        0 |           6 | 2017-12-21 23:01:28.286397+00:00 | NULL           | NULL                                      |                      | [client=[::1]:54702,user=root,n1]   | r7: sending batch 1 Get to (n1,s1):1                                                                                                                                                                                                                 |
|       3 |        0 |           7 | 2017-12-21 23:01:28.286398+00:00 | NULL           | NULL                                      |                      | [client=[::1]:54702,user=root,n1]   | sending request to local server                                                                                                                                                                                                                      |
|       3 |        2 |           0 | 2017-12-21 23:01:28.2864+00:00   | 51µs163ns      | /cockroach.roachpb.Internal/Batch         |                      |                                     | === SPAN START: /cockroach.roachpb.Internal/Batch ===                                                                                                                                                                                                |
|       3 |        2 |           1 | 2017-12-21 23:01:28.286403+00:00 | NULL           | NULL                                      |                      | [n1]                                | 1 Get                                                                                                                                                                                                                                                |
|       3 |        2 |           2 | 2017-12-21 23:01:28.286404+00:00 | NULL           | NULL                                      |                      | [n1]                                | read has no clock uncertainty                                                                                                                                                                                                                        |
|       3 |        2 |           3 | 2017-12-21 23:01:28.286406+00:00 | NULL           | NULL                                      |                      | [n1,s1]                             | executing 1 requests                                                                                                                                                                                                                                 |
|       3 |        2 |           4 | 2017-12-21 23:01:28.286409+00:00 | NULL           | NULL                                      |                      | [n1,s1,r7/1:/Table/{SystemCon…-11}] | read-only path                                                                                                                                                                                                                                       |
|       3 |        2 |           5 | 2017-12-21 23:01:28.286412+00:00 | NULL           | NULL                                      |                      | [n1,s1,r7/1:/Table/{SystemCon…-11}] | command queue                                                                                                                                                                                                                                        |
|       3 |        2 |           6 | 2017-12-21 23:01:28.286415+00:00 | NULL           | NULL                                      |                      | [n1,s1,r7/1:/Table/{SystemCon…-11}] | waiting for read lock                                                                                                                                                                                                                                |
|       3 |        2 |           7 | 2017-12-21 23:01:28.286443+00:00 | NULL           | NULL                                      |                      | [n1,s1,r7/1:/Table/{SystemCon…-11}] | read completed                                                                                                                                                                                                                                       |
|       3 |        0 |           8 | 2017-12-21 23:01:28.286477+00:00 | NULL           | NULL                                      |                      | [client=[::1]:54702,user=root,n1]   | querying next range at /Table/2/1/50/"ramaz"/3/1                                                                                                                                                                                                     |
|       3 |        0 |           9 | 2017-12-21 23:01:28.286489+00:00 | NULL           | NULL                                      |                      | [client=[::1]:54702,user=root,n1]   | r7: sending batch 1 Get to (n1,s1):1                                                                                                                                                                                                                 |
|       3 |        0 |          10 | 2017-12-21 23:01:28.286491+00:00 | NULL           | NULL                                      |                      | [client=[::1]:54702,user=root,n1]   | sending request to local server                                                                                                                                                                                                                      |
|       3 |        3 |           0 | 2017-12-21 23:01:28.286492+00:00 | 42µs770ns      | /cockroach.roachpb.Internal/Batch         |                      |                                     | === SPAN START: /cockroach.roachpb.Internal/Batch ===                                                                                                                                                                                                |
|       3 |        3 |           1 | 2017-12-21 23:01:28.286495+00:00 | NULL           | NULL                                      |                      | [n1]                                | 1 Get                                                                                                                                                                                                                                                |
|       3 |        3 |           2 | 2017-12-21 23:01:28.286496+00:00 | NULL           | NULL                                      |                      | [n1]                                | read has no clock uncertainty                                                                                                                                                                                                                        |
|       3 |        3 |           3 | 2017-12-21 23:01:28.286498+00:00 | NULL           | NULL                                      |                      | [n1,s1]                             | executing 1 requests                                                                                                                                                                                                                                 |
|       3 |        3 |           4 | 2017-12-21 23:01:28.2865+00:00   | NULL           | NULL                                      |                      | [n1,s1,r7/1:/Table/{SystemCon…-11}] | read-only path                                                                                                                                                                                                                                       |
|       3 |        3 |           5 | 2017-12-21 23:01:28.286503+00:00 | NULL           | NULL                                      |                      | [n1,s1,r7/1:/Table/{SystemCon…-11}] | command queue                                                                                                                                                                                                                                        |
|       3 |        3 |           6 | 2017-12-21 23:01:28.286506+00:00 | NULL           | NULL                                      |                      | [n1,s1,r7/1:/Table/{SystemCon…-11}] | waiting for read lock                                                                                                                                                                                                                                |
|       3 |        3 |           7 | 2017-12-21 23:01:28.286525+00:00 | NULL           | NULL                                      |                      | [n1,s1,r7/1:/Table/{SystemCon…-11}] | read completed                                                                                                                                                                                                                                       |
|       3 |        0 |          11 | 2017-12-21 23:01:28.286555+00:00 | NULL           | NULL                                      |                      | [client=[::1]:54702,user=root,n1]   | querying next range at /Table/3/1/2603/2/1                                                                                                                                                                                                           |
|       3 |        0 |          12 | 2017-12-21 23:01:28.286564+00:00 | NULL           | NULL                                      |                      | [client=[::1]:54702,user=root,n1]   | r7: sending batch 1 Get to (n1,s1):1                                                                                                                                                                                                                 |
|       3 |        0 |          13 | 2017-12-21 23:01:28.286565+00:00 | NULL           | NULL                                      |                      | [client=[::1]:54702,user=root,n1]   | sending request to local server                                                                                                                                                                                                                      |
|       3 |        4 |           0 | 2017-12-21 23:01:28.286567+00:00 | 41µs984ns      | /cockroach.roachpb.Internal/Batch         |                      |                                     | === SPAN START: /cockroach.roachpb.Internal/Batch ===                                                                                                                                                                                                |
|       3 |        4 |           1 | 2017-12-21 23:01:28.28657+00:00  | NULL           | NULL                                      |                      | [n1]                                | 1 Get                                                                                                                                                                                                                                                |
|       3 |        4 |           2 | 2017-12-21 23:01:28.286571+00:00 | NULL           | NULL                                      |                      | [n1]                                | read has no clock uncertainty                                                                                                                                                                                                                        |
|       3 |        4 |           3 | 2017-12-21 23:01:28.286573+00:00 | NULL           | NULL                                      |                      | [n1,s1]                             | executing 1 requests                                                                                                                                                                                                                                 |
|       3 |        4 |           4 | 2017-12-21 23:01:28.286575+00:00 | NULL           | NULL                                      |                      | [n1,s1,r7/1:/Table/{SystemCon…-11}] | read-only path                                                                                                                                                                                                                                       |
|       3 |        4 |           5 | 2017-12-21 23:01:28.286578+00:00 | NULL           | NULL                                      |                      | [n1,s1,r7/1:/Table/{SystemCon…-11}] | command queue                                                                                                                                                                                                                                        |
|       3 |        4 |           6 | 2017-12-21 23:01:28.286581+00:00 | NULL           | NULL                                      |                      | [n1,s1,r7/1:/Table/{SystemCon…-11}] | waiting for read lock                                                                                                                                                                                                                                |
|       3 |        4 |           7 | 2017-12-21 23:01:28.2866+00:00   | NULL           | NULL                                      |                      | [n1,s1,r7/1:/Table/{SystemCon…-11}] | read completed                                                                                                                                                                                                                                       |
|       3 |        0 |          14 | 2017-12-21 23:01:28.286647+00:00 | NULL           | NULL                                      |                      | [client=[::1]:54702,user=root,n1]   | querying next range at /Table/3/1/50/2/1                                                                                                                                                                                                             |
|       3 |        0 |          15 | 2017-12-21 23:01:28.286657+00:00 | NULL           | NULL                                      |                      | [client=[::1]:54702,user=root,n1]   | r7: sending batch 1 Get to (n1,s1):1                                                                                                                                                                                                                 |
|       3 |        0 |          16 | 2017-12-21 23:01:28.286658+00:00 | NULL           | NULL                                      |                      | [client=[::1]:54702,user=root,n1]   | sending request to local server                                                                                                                                                                                                                      |
|       3 |        5 |           0 | 2017-12-21 23:01:28.28666+00:00  | 39µs149ns      | /cockroach.roachpb.Internal/Batch         |                      |                                     | === SPAN START: /cockroach.roachpb.Internal/Batch ===                                                                                                                                                                                                |
|       3 |        5 |           1 | 2017-12-21 23:01:28.286662+00:00 | NULL           | NULL                                      |                      | [n1]                                | 1 Get                                                                                                                                                                                                                                                |
|       3 |        5 |           2 | 2017-12-21 23:01:28.286664+00:00 | NULL           | NULL                                      |                      | [n1]                                | read has no clock uncertainty                                                                                                                                                                                                                        |
|       3 |        5 |           3 | 2017-12-21 23:01:28.286666+00:00 | NULL           | NULL                                      |                      | [n1,s1]                             | executing 1 requests                                                                                                                                                                                                                                 |
|       3 |        5 |           4 | 2017-12-21 23:01:28.286668+00:00 | NULL           | NULL                                      |                      | [n1,s1,r7/1:/Table/{SystemCon…-11}] | read-only path                                                                                                                                                                                                                                       |
|       3 |        5 |           5 | 2017-12-21 23:01:28.286671+00:00 | NULL           | NULL                                      |                      | [n1,s1,r7/1:/Table/{SystemCon…-11}] | command queue                                                                                                                                                                                                                                        |
|       3 |        5 |           6 | 2017-12-21 23:01:28.286674+00:00 | NULL           | NULL                                      |                      | [n1,s1,r7/1:/Table/{SystemCon…-11}] | waiting for read lock                                                                                                                                                                                                                                |
|       3 |        5 |           7 | 2017-12-21 23:01:28.286693+00:00 | NULL           | NULL                                      |                      | [n1,s1,r7/1:/Table/{SystemCon…-11}] | read completed                                                                                                                                                                                                                                       |
|       3 |        0 |          17 | 2017-12-21 23:01:28.28672+00:00  | NULL           | NULL                                      |                      | [client=[::1]:54702,user=root,n1]   | query not supported for distSQL: unsupported node *sql.dropTableNode                                                                                                                                                                                 |
|       3 |        0 |          18 | 2017-12-21 23:01:28.286756+00:00 | NULL           | NULL                                      |                      | [client=[::1]:54702,user=root,n1]   | querying next range at /Table/SystemConfigSpan/Start                                                                                                                                                                                                 |
|       3 |        0 |          19 | 2017-12-21 23:01:28.286766+00:00 | NULL           | NULL                                      |                      | [client=[::1]:54702,user=root,n1]   | r7: sending batch 1 Put, 1 BeginTxn to (n1,s1):1                                                                                                                                                                                                     |
|       3 |        0 |          20 | 2017-12-21 23:01:28.286768+00:00 | NULL           | NULL                                      |                      | [client=[::1]:54702,user=root,n1]   | sending request to local server                                                                                                                                                                                                                      |
|       3 |        6 |           0 | 2017-12-21 23:01:28.28677+00:00  | 470µs285ns     | /cockroach.roachpb.Internal/Batch         |                      |                                     | === SPAN START: /cockroach.roachpb.Internal/Batch ===                                                                                                                                                                                                |
|       3 |        6 |           1 | 2017-12-21 23:01:28.286772+00:00 | NULL           | NULL                                      |                      | [n1]                                | 1 Put, 1 BeginTxn                                                                                                                                                                                                                                    |
|       3 |        6 |           2 | 2017-12-21 23:01:28.286773+00:00 | NULL           | NULL                                      |                      | [n1]                                | read has no clock uncertainty                                                                                                                                                                                                                        |
|       3 |        6 |           3 | 2017-12-21 23:01:28.286775+00:00 | NULL           | NULL                                      |                      | [n1,s1]                             | executing 2 requests                                                                                                                                                                                                                                 |
|       3 |        6 |           4 | 2017-12-21 23:01:28.286778+00:00 | NULL           | NULL                                      |                      | [n1,s1,r7/1:/Table/{SystemCon…-11}] | read-write path                                                                                                                                                                                                                                      |
|       3 |        6 |           5 | 2017-12-21 23:01:28.286783+00:00 | NULL           | NULL                                      |                      | [n1,s1,r7/1:/Table/{SystemCon…-11}] | command queue                                                                                                                                                                                                                                        |
|       3 |        6 |           6 | 2017-12-21 23:01:28.286796+00:00 | NULL           | NULL                                      |                      | [n1,s1,r7/1:/Table/{SystemCon…-11}] | applied timestamp cache                                                                                                                                                                                                                              |
|       3 |        6 |           7 | 2017-12-21 23:01:28.286886+00:00 | NULL           | NULL                                      |                      | [n1,s1,r7/1:/Table/{SystemCon…-11}] | evaluated request                                                                                                                                                                                                                                    |
|       3 |        6 |           8 | 2017-12-21 23:01:28.286896+00:00 | NULL           | NULL                                      |                      | [n1,s1,r7/1:/Table/{SystemCon…-11}] | acquired {raft,replica}mu                                                                                                                                                                                                                            |
|       3 |        6 |           9 | 2017-12-21 23:01:28.287147+00:00 | NULL           | NULL                                      |                      | [n1,s1,r7/1:/Table/{SystemCon…-11}] | applying command                                                                                                                                                                                                                                     |
|       3 |        0 |          21 | 2017-12-21 23:01:28.28725+00:00  | NULL           | NULL                                      |                      | [client=[::1]:54702,user=root,n1]   | coordinator spawns                                                                                                                                                                                                                                   |
|       3 |        7 |           0 | 2017-12-21 23:01:28.287255+00:00 | 9ms867µs422ns  | [async] kv.TxnCoordSender: heartbeat loop |                      |                                     | === SPAN START: [async] kv.TxnCoordSender: heartbeat loop ===                                                                                                                                                                                        |
|       3 |        0 |          22 | 2017-12-21 23:01:28.287383+00:00 | NULL           | NULL                                      |                      | [client=[::1]:54702,user=root,n1]   | querying next range at /Table/2/1/0/"system"/3/1                                                                                                                                                                                                     |
|       3 |        0 |          23 | 2017-12-21 23:01:28.287398+00:00 | NULL           | NULL                                      |                      | [client=[::1]:54702,user=root,n1]   | r7: sending batch 1 Get to (n1,s1):1                                                                                                                                                                                                                 |
|       3 |        0 |          24 | 2017-12-21 23:01:28.287399+00:00 | NULL           | NULL                                      |                      | [client=[::1]:54702,user=root,n1]   | sending request to local server                                                                                                                                                                                                                      |
|       3 |        8 |           0 | 2017-12-21 23:01:28.287401+00:00 | 65µs973ns      | /cockroach.roachpb.Internal/Batch         |                      |                                     | === SPAN START: /cockroach.roachpb.Internal/Batch ===                                                                                                                                                                                                |
|       3 |        8 |           1 | 2017-12-21 23:01:28.287404+00:00 | NULL           | NULL                                      |                      | [n1]                                | 1 Get                                                                                                                                                                                                                                                |
|       3 |        8 |           2 | 2017-12-21 23:01:28.287406+00:00 | NULL           | NULL                                      |                      | [n1]                                | read has no clock uncertainty                                                                                                                                                                                                                        |
|       3 |        8 |           3 | 2017-12-21 23:01:28.287409+00:00 | NULL           | NULL                                      |                      | [n1,s1]                             | executing 1 requests                                                                                                                                                                                                                                 |
|       3 |        8 |           4 | 2017-12-21 23:01:28.287412+00:00 | NULL           | NULL                                      |                      | [n1,s1,r7/1:/Table/{SystemCon…-11}] | read-only path                                                                                                                                                                                                                                       |
|       3 |        8 |           5 | 2017-12-21 23:01:28.287417+00:00 | NULL           | NULL                                      |                      | [n1,s1,r7/1:/Table/{SystemCon…-11}] | command queue                                                                                                                                                                                                                                        |
|       3 |        8 |           6 | 2017-12-21 23:01:28.287421+00:00 | NULL           | NULL                                      |                      | [n1,s1,r7/1:/Table/{SystemCon…-11}] | waiting for read lock                                                                                                                                                                                                                                |
|       3 |        8 |           7 | 2017-12-21 23:01:28.287459+00:00 | NULL           | NULL                                      |                      | [n1,s1,r7/1:/Table/{SystemCon…-11}] | read completed                                                                                                                                                                                                                                       |
|       3 |        0 |          25 | 2017-12-21 23:01:28.287513+00:00 | NULL           | NULL                                      |                      | [client=[::1]:54702,user=root,n1]   | querying next range at /Table/3/1/1/2/1                                                                                                                                                                                                              |
|       3 |        0 |          26 | 2017-12-21 23:01:28.287524+00:00 | NULL           | NULL                                      |                      | [client=[::1]:54702,user=root,n1]   | r7: sending batch 1 Get to (n1,s1):1                                                                                                                                                                                                                 |
|       3 |        0 |          27 | 2017-12-21 23:01:28.287525+00:00 | NULL           | NULL                                      |                      | [client=[::1]:54702,user=root,n1]   | sending request to local server                                                                                                                                                                                                                      |
|       3 |        9 |           0 | 2017-12-21 23:01:28.287527+00:00 | 52µs389ns      | /cockroach.roachpb.Internal/Batch         |                      |                                     | === SPAN START: /cockroach.roachpb.Internal/Batch ===                                                                                                                                                                                                |
|       3 |        9 |           1 | 2017-12-21 23:01:28.287531+00:00 | NULL           | NULL                                      |                      | [n1]                                | 1 Get                                                                                                                                                                                                                                                |
|       3 |        9 |           2 | 2017-12-21 23:01:28.287533+00:00 | NULL           | NULL                                      |                      | [n1]                                | read has no clock uncertainty                                                                                                                                                                                                                        |
|       3 |        9 |           3 | 2017-12-21 23:01:28.287535+00:00 | NULL           | NULL                                      |                      | [n1,s1]                             | executing 1 requests                                                                                                                                                                                                                                 |
|       3 |        9 |           4 | 2017-12-21 23:01:28.287538+00:00 | NULL           | NULL                                      |                      | [n1,s1,r7/1:/Table/{SystemCon…-11}] | read-only path                                                                                                                                                                                                                                       |
|       3 |        9 |           5 | 2017-12-21 23:01:28.287541+00:00 | NULL           | NULL                                      |                      | [n1,s1,r7/1:/Table/{SystemCon…-11}] | command queue                                                                                                                                                                                                                                        |
|       3 |        9 |           6 | 2017-12-21 23:01:28.287545+00:00 | NULL           | NULL                                      |                      | [n1,s1,r7/1:/Table/{SystemCon…-11}] | waiting for read lock                                                                                                                                                                                                                                |
|       3 |        9 |           7 | 2017-12-21 23:01:28.287573+00:00 | NULL           | NULL                                      |                      | [n1,s1,r7/1:/Table/{SystemCon…-11}] | read completed                                                                                                                                                                                                                                       |
|       3 |        0 |          28 | 2017-12-21 23:01:28.287606+00:00 | NULL           | NULL                                      |                      | [client=[::1]:54702,user=root,n1]   | querying next range at /Table/2/1/1/"eventlog"/3/1                                                                                                                                                                                                   |
|       3 |        0 |          29 | 2017-12-21 23:01:28.287616+00:00 | NULL           | NULL                                      |                      | [client=[::1]:54702,user=root,n1]   | r7: sending batch 1 Get to (n1,s1):1                                                                                                                                                                                                                 |
|       3 |        0 |          30 | 2017-12-21 23:01:28.287617+00:00 | NULL           | NULL                                      |                      | [client=[::1]:54702,user=root,n1]   | sending request to local server                                                                                                                                                                                                                      |
|       3 |       10 |           0 | 2017-12-21 23:01:28.287619+00:00 | 45µs227ns      | /cockroach.roachpb.Internal/Batch         |                      |                                     | === SPAN START: /cockroach.roachpb.Internal/Batch ===                                                                                                                                                                                                |
|       3 |       10 |           1 | 2017-12-21 23:01:28.287621+00:00 | NULL           | NULL                                      |                      | [n1]                                | 1 Get                                                                                                                                                                                                                                                |
|       3 |       10 |           2 | 2017-12-21 23:01:28.287623+00:00 | NULL           | NULL                                      |                      | [n1]                                | read has no clock uncertainty                                                                                                                                                                                                                        |
|       3 |       10 |           3 | 2017-12-21 23:01:28.287625+00:00 | NULL           | NULL                                      |                      | [n1,s1]                             | executing 1 requests                                                                                                                                                                                                                                 |
|       3 |       10 |           4 | 2017-12-21 23:01:28.287628+00:00 | NULL           | NULL                                      |                      | [n1,s1,r7/1:/Table/{SystemCon…-11}] | read-only path                                                                                                                                                                                                                                       |
|       3 |       10 |           5 | 2017-12-21 23:01:28.287631+00:00 | NULL           | NULL                                      |                      | [n1,s1,r7/1:/Table/{SystemCon…-11}] | command queue                                                                                                                                                                                                                                        |
|       3 |       10 |           6 | 2017-12-21 23:01:28.287633+00:00 | NULL           | NULL                                      |                      | [n1,s1,r7/1:/Table/{SystemCon…-11}] | waiting for read lock                                                                                                                                                                                                                                |
|       3 |       10 |           7 | 2017-12-21 23:01:28.287658+00:00 | NULL           | NULL                                      |                      | [n1,s1,r7/1:/Table/{SystemCon…-11}] | read completed                                                                                                                                                                                                                                       |
|       3 |        0 |          31 | 2017-12-21 23:01:28.287682+00:00 | NULL           | NULL                                      |                      | [client=[::1]:54702,user=root,n1]   | querying next range at /Table/3/1/12/2/1                                                                                                                                                                                                             |
|       3 |        0 |          32 | 2017-12-21 23:01:28.287691+00:00 | NULL           | NULL                                      |                      | [client=[::1]:54702,user=root,n1]   | r7: sending batch 1 Get to (n1,s1):1                                                                                                                                                                                                                 |
|       3 |        0 |          33 | 2017-12-21 23:01:28.287692+00:00 | NULL           | NULL                                      |                      | [client=[::1]:54702,user=root,n1]   | sending request to local server                                                                                                                                                                                                                      |
|       3 |       11 |           0 | 2017-12-21 23:01:28.287697+00:00 | 44µs921ns      | /cockroach.roachpb.Internal/Batch         |                      |                                     | === SPAN START: /cockroach.roachpb.Internal/Batch ===                                                                                                                                                                                                |
|       3 |       11 |           1 | 2017-12-21 23:01:28.2877+00:00   | NULL           | NULL                                      |                      | [n1]                                | 1 Get                                                                                                                                                                                                                                                |
|       3 |       11 |           2 | 2017-12-21 23:01:28.287701+00:00 | NULL           | NULL                                      |                      | [n1]                                | read has no clock uncertainty                                                                                                                                                                                                                        |
|       3 |       11 |           3 | 2017-12-21 23:01:28.287703+00:00 | NULL           | NULL                                      |                      | [n1,s1]                             | executing 1 requests                                                                                                                                                                                                                                 |
|       3 |       11 |           4 | 2017-12-21 23:01:28.287705+00:00 | NULL           | NULL                                      |                      | [n1,s1,r7/1:/Table/{SystemCon…-11}] | read-only path                                                                                                                                                                                                                                       |
|       3 |       11 |           5 | 2017-12-21 23:01:28.287708+00:00 | NULL           | NULL                                      |                      | [n1,s1,r7/1:/Table/{SystemCon…-11}] | command queue                                                                                                                                                                                                                                        |
|       3 |       11 |           6 | 2017-12-21 23:01:28.28771+00:00  | NULL           | NULL                                      |                      | [n1,s1,r7/1:/Table/{SystemCon…-11}] | waiting for read lock                                                                                                                                                                                                                                |
|       3 |       11 |           7 | 2017-12-21 23:01:28.287736+00:00 | NULL           | NULL                                      |                      | [n1,s1,r7/1:/Table/{SystemCon…-11}] | read completed                                                                                                                                                                                                                                       |
|       3 |        0 |          34 | 2017-12-21 23:01:28.287787+00:00 | NULL           | NULL                                      |                      | [client=[::1]:54702,user=root,n1]   | querying next range at /Table/3/1/1/2/1                                                                                                                                                                                                              |
|       3 |        0 |          35 | 2017-12-21 23:01:28.287797+00:00 | NULL           | NULL                                      |                      | [client=[::1]:54702,user=root,n1]   | r7: sending batch 1 Get to (n1,s1):1                                                                                                                                                                                                                 |
|       3 |        0 |          36 | 2017-12-21 23:01:28.287798+00:00 | NULL           | NULL                                      |                      | [client=[::1]:54702,user=root,n1]   | sending request to local server                                                                                                                                                                                                                      |
|       3 |       12 |           0 | 2017-12-21 23:01:28.2878+00:00   | 45µs45ns       | /cockroach.roachpb.Internal/Batch         |                      |                                     | === SPAN START: /cockroach.roachpb.Internal/Batch ===                                                                                                                                                                                                |
|       3 |       12 |           1 | 2017-12-21 23:01:28.287802+00:00 | NULL           | NULL                                      |                      | [n1]                                | 1 Get                                                                                                                                                                                                                                                |
|       3 |       12 |           2 | 2017-12-21 23:01:28.287803+00:00 | NULL           | NULL                                      |                      | [n1]                                | read has no clock uncertainty                                                                                                                                                                                                                        |
|       3 |       12 |           3 | 2017-12-21 23:01:28.287805+00:00 | NULL           | NULL                                      |                      | [n1,s1]                             | executing 1 requests                                                                                                                                                                                                                                 |
|       3 |       12 |           4 | 2017-12-21 23:01:28.287808+00:00 | NULL           | NULL                                      |                      | [n1,s1,r7/1:/Table/{SystemCon…-11}] | read-only path                                                                                                                                                                                                                                       |
|       3 |       12 |           5 | 2017-12-21 23:01:28.287811+00:00 | NULL           | NULL                                      |                      | [n1,s1,r7/1:/Table/{SystemCon…-11}] | command queue                                                                                                                                                                                                                                        |
|       3 |       12 |           6 | 2017-12-21 23:01:28.287813+00:00 | NULL           | NULL                                      |                      | [n1,s1,r7/1:/Table/{SystemCon…-11}] | waiting for read lock                                                                                                                                                                                                                                |
|       3 |       12 |           7 | 2017-12-21 23:01:28.287839+00:00 | NULL           | NULL                                      |                      | [n1,s1,r7/1:/Table/{SystemCon…-11}] | read completed                                                                                                                                                                                                                                       |
|       3 |        0 |          37 | 2017-12-21 23:01:28.287974+00:00 | NULL           | NULL                                      |                      | [client=[::1]:54702,user=root,n1]   | querying next range at /Table/12/1/2017-12-21T23:01:28.286045Z/"D\x84KYo\x93Jт)\xf8a\xaa\xb2\xfe6"/0                                                                                                                                                 |
|       3 |        0 |          38 | 2017-12-21 23:01:28.287984+00:00 | NULL           | NULL                                      |                      | [client=[::1]:54702,user=root,n1]   | r9: sending batch 5 CPut to (n1,s1):1                                                                                                                                                                                                                |
|       3 |        0 |          39 | 2017-12-21 23:01:28.287986+00:00 | NULL           | NULL                                      |                      | [client=[::1]:54702,user=root,n1]   | sending request to local server                                                                                                                                                                                                                      |
|       3 |       13 |           0 | 2017-12-21 23:01:28.287988+00:00 | 368µs81ns      | /cockroach.roachpb.Internal/Batch         |                      |                                     | === SPAN START: /cockroach.roachpb.Internal/Batch ===                                                                                                                                                                                                |
|       3 |       13 |           1 | 2017-12-21 23:01:28.28799+00:00  | NULL           | NULL                                      |                      | [n1]                                | 5 CPut                                                                                                                                                                                                                                               |
|       3 |       13 |           2 | 2017-12-21 23:01:28.287991+00:00 | NULL           | NULL                                      |                      | [n1]                                | read has no clock uncertainty                                                                                                                                                                                                                        |
|       3 |       13 |           3 | 2017-12-21 23:01:28.287994+00:00 | NULL           | NULL                                      |                      | [n1,s1]                             | executing 5 requests                                                                                                                                                                                                                                 |
|       3 |       13 |           4 | 2017-12-21 23:01:28.287997+00:00 | NULL           | NULL                                      |                      | [n1,s1,r9/1:/Table/1{2-3}]          | read-write path                                                                                                                                                                                                                                      |
|       3 |       13 |           5 | 2017-12-21 23:01:28.288002+00:00 | NULL           | NULL                                      |                      | [n1,s1,r9/1:/Table/1{2-3}]          | command queue                                                                                                                                                                                                                                        |
|       3 |       13 |           6 | 2017-12-21 23:01:28.288019+00:00 | NULL           | NULL                                      |                      | [n1,s1,r9/1:/Table/1{2-3}]          | applied timestamp cache                                                                                                                                                                                                                              |
|       3 |       13 |           7 | 2017-12-21 23:01:28.288098+00:00 | NULL           | NULL                                      |                      | [n1,s1,r9/1:/Table/1{2-3}]          | evaluated request                                                                                                                                                                                                                                    |
|       3 |       13 |           8 | 2017-12-21 23:01:28.288104+00:00 | NULL           | NULL                                      |                      | [n1,s1,r9/1:/Table/1{2-3}]          | acquired {raft,replica}mu                                                                                                                                                                                                                            |
|       3 |       13 |           9 | 2017-12-21 23:01:28.288279+00:00 | NULL           | NULL                                      |                      | [n1,s1,r9/1:/Table/1{2-3}]          | applying command                                                                                                                                                                                                                                     |
|       3 |        0 |          40 | 2017-12-21 23:01:28.28843+00:00  | NULL           | NULL                                      |                      | [client=[::1]:54702,user=root,n1]   | querying next range at /Table/SystemConfigSpan/Start                                                                                                                                                                                                 |
|       3 |        0 |          41 | 2017-12-21 23:01:28.288449+00:00 | NULL           | NULL                                      |                      | [client=[::1]:54702,user=root,n1]   | r7: sending batch 1 EndTxn to (n1,s1):1                                                                                                                                                                                                              |
|       3 |        0 |          42 | 2017-12-21 23:01:28.288451+00:00 | NULL           | NULL                                      |                      | [client=[::1]:54702,user=root,n1]   | sending request to local server                                                                                                                                                                                                                      |
|       3 |       14 |           0 | 2017-12-21 23:01:28.288454+00:00 | 8ms560µs609ns  | /cockroach.roachpb.Internal/Batch         |                      |                                     | === SPAN START: /cockroach.roachpb.Internal/Batch ===                                                                                                                                                                                                |
|       3 |       14 |           1 | 2017-12-21 23:01:28.288457+00:00 | NULL           | NULL                                      |                      | [n1]                                | 1 EndTxn                                                                                                                                                                                                                                             |
|       3 |       14 |           2 | 2017-12-21 23:01:28.288458+00:00 | NULL           | NULL                                      |                      | [n1]                                | read has no clock uncertainty                                                                                                                                                                                                                        |
|       3 |       14 |           3 | 2017-12-21 23:01:28.288461+00:00 | NULL           | NULL                                      |                      | [n1,s1]                             | executing 1 requests                                                                                                                                                                                                                                 |
|       3 |       14 |           4 | 2017-12-21 23:01:28.288464+00:00 | NULL           | NULL                                      |                      | [n1,s1,r7/1:/Table/{SystemCon…-11}] | read-write path                                                                                                                                                                                                                                      |
|       3 |       14 |           5 | 2017-12-21 23:01:28.28847+00:00  | NULL           | NULL                                      |                      | [n1,s1,r7/1:/Table/{SystemCon…-11}] | command queue                                                                                                                                                                                                                                        |
|       3 |       14 |           6 | 2017-12-21 23:01:28.288479+00:00 | NULL           | NULL                                      |                      | [n1,s1,r7/1:/Table/{SystemCon…-11}] | applied timestamp cache                                                                                                                                                                                                                              |
|       3 |       14 |           7 | 2017-12-21 23:01:28.288575+00:00 | NULL           | NULL                                      |                      | [n1,s1,r7/1:/Table/{SystemCon…-11}] | evaluated request                                                                                                                                                                                                                                    |
|       3 |       14 |           8 | 2017-12-21 23:01:28.288582+00:00 | NULL           | NULL                                      |                      | [n1,s1,r7/1:/Table/{SystemCon…-11}] | acquired {raft,replica}mu                                                                                                                                                                                                                            |
|       3 |       14 |           9 | 2017-12-21 23:01:28.288754+00:00 | NULL           | NULL                                      |                      | [n1,s1,r7/1:/Table/{SystemCon…-11}] | applying command                                                                                                                                                                                                                                     |
|       3 |       14 |          10 | 2017-12-21 23:01:28.296891+00:00 | NULL           | NULL                                      |                      | [n1,s1,r7/1:/Table/{SystemCon…-11}] | gossiping system config                                                                                                                                                                                                                              |
|       3 |        0 |          43 | 2017-12-21 23:01:28.297036+00:00 | NULL           | NULL                                      |                      | [client=[::1]:54702,user=root,n1]   | coordinator stops                                                                                                                                                                                                                                    |
|       3 |        0 |          44 | 2017-12-21 23:01:28.29707+00:00  | NULL           | NULL                                      | sql/event_log.go:113 | [client=[::1]:54702,user=root,n1]   | Event: "drop_table", target: 2603, info: {TableName:ramaz Statement:DROP TABLE ramaz User:root CascadeDroppedViews:[]}                                                                                                                               |
|       3 |        0 |          45 | 2017-12-21 23:01:28.297142+00:00 | NULL           | NULL                                      |                      | [client=[::1]:54702,user=root,n1]   | AutoCommit. err: <nil>␤                                                                                                                                                                                                                              |
|         |          |             |                                  |                |                                           |                      |                                     | txn: "sql txn implicit" id=f14f000a key=/Table/SystemConfigSpan/Start rw=true pri=0.06770245 iso=SERIALIZABLE stat=COMMITTED epo=0 ts=1513897288.286045331,0 orig=1513897288.286045331,0 max=1513897288.786045331,0 wto=false rop=false seq=14 int=5 |
|       4 |        0 |           0 | 2017-12-21 23:01:28.348853+00:00 | 89µs947ns      | sql txn implicit                          |                      |                                     | === SPAN START: sql txn implicit ===                                                                                                                                                                                                                 |
|       4 |        0 |           1 | 2017-12-21 23:01:28.348882+00:00 | NULL           | NULL                                      |                      | [client=[::1]:54702,user=root,n1]   | executing 1/1: SHOW TRANSACTION STATUS                                                                                                                                                                                                               |
|       4 |        0 |           2 | 2017-12-21 23:01:28.348939+00:00 | NULL           | NULL                                      |                      | [client=[::1]:54702,user=root,n1]   | AutoCommit. err: <nil>␤                                                                                                                                                                                                                              |
|         |          |             |                                  |                |                                           |                      |                                     | txn: "sql txn implicit" id=6da1bdc0 key=/Min rw=false pri=0.02484401 iso=SERIALIZABLE stat=COMMITTED epo=0 ts=1513897288.348862261,0 orig=1513897288.348862261,0 max=1513897288.848862261,0 wto=false rop=false seq=1                                |
|       5 |        0 |           0 | 2017-12-21 23:01:28.349049+00:00 | 220µs320ns     | sql txn implicit                          |                      |                                     | === SPAN START: sql txn implicit ===                                                                                                                                                                                                                 |
|       5 |        0 |           1 | 2017-12-21 23:01:28.349082+00:00 | NULL           | NULL                                      |                      | [client=[::1]:54702,user=root,n1]   | executing 1/1: SHOW database                                                                                                                                                                                                                         |
|       5 |        0 |           2 | 2017-12-21 23:01:28.34921+00:00  | NULL           | NULL                                      |                      | [client=[::1]:54702,user=root,n1]   | query not supported for distSQL: unsupported node *sql.valuesNode without SQL VALUES clause                                                                                                                                                          |
|       5 |        0 |           3 | 2017-12-21 23:01:28.349265+00:00 | NULL           | NULL                                      |                      | [client=[::1]:54702,user=root,n1]   | AutoCommit. err: <nil>␤                                                                                                                                                                                                                              |
|         |          |             |                                  |                |                                           |                      |                                     | txn: "sql txn implicit" id=eb471efb key=/Min rw=false pri=0.16706726 iso=SERIALIZABLE stat=COMMITTED epo=0 ts=1513897288.349057011,0 orig=1513897288.349057011,0 max=1513897288.849057011,0 wto=false rop=false seq=1                                |
|       6 |        0 |           0 | 2017-12-21 23:01:32.550819+00:00 | NULL           | sql txn implicit                          |                      |                                     | === SPAN START: sql txn implicit ===                                                                                                                                                                                                                 |
|       6 |        0 |           1 | 2017-12-21 23:01:32.550855+00:00 | NULL           | NULL                                      |                      | [client=[::1]:54702,user=root,n1]   | executing 1/1: SET tracing = off                                                                                                                                                                                                                     |
|       6 |        0 |           2 | 2017-12-21 23:01:32.550888+00:00 | NULL           | NULL                                      |                      | [client=[::1]:54702,user=root,n1]   | query not supported for distSQL: SET / SET CLUSTER SETTING should never distribute                                                                                                                                                                   |
+---------+----------+-------------+----------------------------------+----------------+-------------------------------------------+----------------------+-------------------------------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
(177 rows)

I also ran the experiment doing SELECT * FROM pg_x tables, and they did increase but only a fractional amount. The first span appears to spend all it's time at the beginning of the transaction, before plan execution. That would mean all of the time is being spent in the planner. This might be from work being done during virtual table populate calls, or other places where they iterate over all of the descriptors.

The second span, for drop table, seems to not reflect any of the time spent in within the transaction. I would guess a big chunk of this is coming from after the transaction during execSchemaChangers. Again, this could be something related to having to iterate over a lot of table descriptors.

During these tests, the GC time was not modified so I would assume the table descriptors were hanging around (although, the single node cluster was down for a week, should it have been cleaned out?)

@nvanbenschoten
Copy link
Member

Thanks for the work here @LEGO! I played around with your gist to get more insight into why DROP TABLE gets slower over time and a few things stuck out. The first is that I was able to trace the source of the performance degradation to SchemaChanger, as you had speculated. A brief audit of SchemaChanger didn't find any serious badness other than a number of unoptimized transactions that could take advantage of txn.CommitInBatch. Playing around with this did seem to help speed parts of the schema change up a little bit (~10-20%) because it avoided a few round trips, but it didn't relieve the larger issue.

I dug down deeper into the cause of the slowness in SchemaChanger and was surprised to find that a number of its methods seemed to get slower as the test progressed. Instead of a single point of slowness, methods like AcquireLease, ReleaseLease, DropTableName, and maybeAddDropRename all scaled about the same: linearly w.r.t the number of tables dropped, as your plot demonstrates. The slowness between these methods traced all the way down past replica proposal, but shockingly, the issue didn't seem to come directly from RocksDB insertions like I expected. I continued to trace it down to handleLocalEvalResult and then finally to MaybeGossipSystemConfig. It turns out that MaybeGossipSystemConfig includes a call to loadSystemConfig, which scans the entire SystemConfigSpan. This span must have been growing with each new table that was added and deleted because it contained thousands of kvs by the time DROP TABLE statements started taking ~80ms. Thinking back, I had seen the slowness across a number of different operations in SchemaChanger. This now made sense, because any Txn that SetSystemConfigTrigger would hit this slowdown.

I'm not familiar enough with how the system config works to know what the best course of action here is. At the very least, MaybeGossipSystemConfig is already an asynchronous process, so pulling it out of the synchronous hot path should be a clear win. To test this, I threw it in a goroutine and DROP TABLE magically got 5x faster. After this, things seemed to run a lot smoother, but I still did see that occasional ~10ms Raft log sync. I not sure what to make of this at the moment.

Overall, it seems like there could be a few easy wins related to gossiping the system config now that we know its a bottleneck for certain access patterns:

  • we could make the process beneath Raft asynchronous
  • we could coalesce multiple calls to MaybeGossipSystemConfig together
  • we could simply drop calls to MaybeGossipSystemConfig when we see too many
  • we might be able to do a better job keeping the size of the system config down when tables are deleted

The method is "best effort", but I don't know the implications of a failure to gossip the system config well enough to weigh the relative tradeoffs here. @vivekmenezes or @mberhault, perhaps you could shed some light on this for me.

@petermattis
Copy link
Collaborator

Nice debugging!

we could make the process beneath Raft asynchronous

Yes, we should definitely do this.

we could coalesce multiple calls to MaybeGossipSystemConfig together

Yes.

we could simply drop calls to MaybeGossipSystemConfig when we see too many

I don't think we can drop the calls as schema changes rely on nodes getting the updated table descriptors gossiped in a timely manner. I think aggressive coalescing would be sufficient. This would be similar to how we coalesce WAL sync calls in rocksdb.go.

Something I'm not clear on: is the test creating and dropping tables fast enough that coalescing of the system config gossip calls would have an effect?

we might be able to do a better job keeping the size of the system config down when tables are deleted

Are we writing a tombstone for deleted tables? In your testing here, how large is the system config that is gossiped? How many key/values does it contain?

#21334 might help significantly as scanning over tombstones will take place entirely in C++.

The method is "best effort", but I don't know the implications of a failure to gossip the system config well enough to weigh the relative tradeoffs here.

If we don't gossip the system config, schema changes will not make progress. There may be some other badness as well. I'm pretty sure nothing relies on the system config being gossiped synchronously.

@vivekmenezes
Copy link
Contributor

vivekmenezes commented Jan 9, 2018 via email

@vivekmenezes
Copy link
Contributor

vivekmenezes commented Jan 9, 2018 via email

@nvanbenschoten
Copy link
Member

  • we could make the process beneath Raft asynchronous
  • we could coalesce multiple calls to MaybeGossipSystemConfig together

Adding a new systemConfigGossipQueue with a small delay (~10ms) addresses both of these concerns. Adding the queue beneath Raft instead of performing the scan immediately provides the asynchronous property and delaying the queue processing for a small amount of time helps coalesce multiple requests together. However, the introduction of this queue only seemed to help with certain workloads, not all. With a DROP TABLE-only workload (create and drop in a loop), we see the following improvement with the new queue:

final

Unfortunately, those numbers don't translate over to the full workload @LEGO provided. In fact, when run with the full workload, the change only seems to provide about a 20% improvement. I spent a while trying to figure out why this is and it looks like the issue has to do with table leases. After creating each table, the full workload inserts and queries the table. These operations require a table lease to be acquired on each table. Unfortunately, the acquisition of this table lease re-establishes the dependency of the DROP TABLE on the gossip of the SystemConfig span, effectively putting MaybeGossipSystemConfig back on the hot path. The reason for this is because SchemaChanger calls LeaseStore.WaitForOneVersion multiple times when performing DROP TABLE. This operation waits for a single version of the table lease to be present and for all old leases on the table to be released. This will only happen when all leaseholders hear the gossip update and upgrade their table lease, purging old versions in turn. With MaybeGossipSystemConfig back on the hot path, the change doesn't provide nearly the improvement I had hoped.

This is pretty bad. The more I explore, the further away the low hanging fruit appears. To summarize:

  • DROP TABLE does not delete table descriptors immediately, it waits for their GC deadline.
  • This means that the SystemConfig span can easily hold thousands of descriptors, which take 10s of ms to scan. @petermattis is this still surprising to you? Scans on similarly sized tables (~1500 keys, ~5 versions each, ~512B values) seem to perform about the same.
  • SchemaChanger performs multiple operations that SetSystemConfigTrigger, which currently scans the SystemConfig span synchronously.
  • Even if this is async beneath Raft, SchemaChanger waits on old table leases to be released at least twice synchronously. These releases are triggered by SystemConfig gossip updates.

The only change I've made so far that actually seems worthwhile performance-wise is caching results on the receiving side of SystemConfig gossip updates. By hashing each key and value in the update and comparing against previous results, we can almost always avoid unnecessary proto unmarshalling and repeated work. Adding this small change to

case <-gossipUpdateC:
cfg, _ := s.gossip.GetSystemConfig()
// Read all tables and their versions
provided about a 20% speedup on the DROP TABLE-only workload (without the systemConfigGossipQueue). I suspect that this technique could be applied in a number of places.

@vivekmenezes
Copy link
Contributor

The last time I looked at this I remember LeaseStore.WaitForOneVersion() having rather unpredictable performance. I think it might be the case that it polls and each retry waits for a longer time than it need. There could also be retries caused by transaction retries due to contention.

@petermattis
Copy link
Collaborator

DROP TABLE does not delete table descriptors immediately, it waits for their GC deadline.

Ah, I had forgotten about that recent change.

This means that the SystemConfig span can easily hold thousands of descriptors, which take 10s of ms to scan. @petermattis is this still surprising to you? Scans on similarly sized tables (~1500 keys, ~5 versions each, ~512B values) seem to perform about the same.

Yes, these timings make sense.

Thinking a bit radically here, perhaps we can gossip only the changed system config values. We'd still need to have a fallback path to gossip the entire system config range when a replica acquires the lease for the system config range, but when mutating a small set of keys it should be safe to have a different gossip key (i.e. "system-db-delta") that just contains the updated key/values. I'm not sure how difficult it would be to plumb the affected keys. And I'm not sure how difficult it would be to receive a delta. Just brainstorming a bit. Reading thousands of keys is going to take a bit of time.

@nvanbenschoten
Copy link
Member

The last time I looked at this I remember LeaseStore.WaitForOneVersion() having rather unpredictable performance.

Yes, LeaseStore.WaitForOneVersion is polling the system.lease table to detect when a lease count drops to 0. This isn't the entire problem, but it is certainly increasing average latency and latency variance.

Thinking a bit radically here, perhaps we can gossip only the changed system config values

I was thinking about ideas like this, but I don't think gossip is the right transport mechanism here because it is best-effort, asynchronous, and could lose deltas if multiple updates overwrote one another. This actually seems like a perfect use case for CDC, where a listener could monitor the SystemConfig range directly and be informed of any updates immediately. In the long-term I agree that this is something that can be improved tremendously.

For now, I've been able to make a series of changes which both captures the previous gains seen in #20753 (comment) and also improves the situation for cases like the full workload where a table has outstanding leases. Below are graphs using @LEGO's workload before the change and after:

Before:

before_change

After:

after_change

The change is on the branch nvanbenschoten/gossipQueue. This is an extreme work-in-progress, but the salient points of the change are:

  • we create a SystemConfigDeltaFilter to avoid processing all SystemConfig
    kvs on each gossip update.
  • we handle Timers better in SchemaChangeManager.
  • we create systemConfigGossipQueue, as discussed above.
  • we notify local goroutines polling on lease releases directly when
    a lease has been released, which avoids polling inefficiencies.

Each of these changes can probably be broken into separate PRs as they're all pretty self-contained.

@nvanbenschoten
Copy link
Member

I also did some investigation into the INTROSPECTION_QUERY. This was pretty straightforward. The query gets slower because each virtual pg_catalog table within the JOIN performs a scan over all descriptors (forEachTableDescWithTableLookup calls GetAllDescriptors). At the very least, we should be able to cache all descriptors for the extent of a Txn so that we're only performing the lookup once for each Txn instead of once for each virtual table accessed within a Txn.

In the case here, the JOIN operates over 6 pg_catalog tables, so we could expect a 6x speedup by caching the descriptors.

nvanbenschoten added a commit to nvanbenschoten/cockroach that referenced this issue Jan 20, 2018
Related to cockroachdb#20753.

Until now, the population of most virtual tables (information_schema,
pg_catalog, crdb_internal) has required a kv scan over all descriptors.
This became expensive for complex introspection queries that joined
multiple virtual tables together, since each would require their own
scan to collect the descriptors. To make this worse, certain workloads
like adding and dropping table repeatedly could generate lots of
descriptors, making each of these scans take a significant amount of
time.

This was pretty bad because we knew that each scan would return the same
results when inside the same query. In fact, we knew that even across
statements but within the same transaction, the results would almost
always be the same unless the transaction itself had done a schema
change.

To address this issue, this change now caches all DescriptorProtos in
TableCollection, clearing them only when necessary. TableCollection
already managed the caching of descriptor-related state like this and
made sure to purge the cache on schema changes and txn restarts, so it
was a natural place for this extra bit of caching to live.

Release note (performance improvement): information_schema and
pg_catalog should be faster to query.
@nvanbenschoten nvanbenschoten added this to the 2.1 milestone Jul 22, 2018
@knz knz changed the title cluster performance degrades after adding and dropping hundreds of tables sql: cluster performance degrades after adding and dropping hundreds of tables Jul 23, 2018
@knz
Copy link
Contributor

knz commented Jul 23, 2018

@nvanbenschoten is this core or is this sql? (Looks more sql to me?)

@knz knz added the A-schema-descriptors Relating to SQL table/db descriptor handling. label Jul 23, 2018
@nvanbenschoten
Copy link
Member

I'm actually going to close this because the remaining work items here are contained in #19267 and #21702. We'll want to address both of those for 2.1 as they are pretty big footguns.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
A-schema-descriptors Relating to SQL table/db descriptor handling. C-performance Perf of queries or internals. Solution not expected to change functional behavior.
Projects
None yet
Development

No branches or pull requests

5 participants