diff --git a/pkg/cli/testdata/merge_logs_crdb-v1/results/1.all b/pkg/cli/testdata/merge_logs_crdb-v1/results/1.all index 586d6b74b71f..718b4422b147 100644 --- a/pkg/cli/testdata/merge_logs_crdb-v1/results/1.all +++ b/pkg/cli/testdata/merge_logs_crdb-v1/results/1.all @@ -1,20 +1,20 @@ -test-0001> I181130 22:14:34.828612 740 storage/store_rebalancer.go:277 [n1,s1,store-rebalancer] load-based lease transfers successfully brought s1 down to 37128.65 qps (mean=29834.62, upperThreshold=37293.27) -test-0001> I181130 22:14:37.516378 441 server/status/runtime.go:465 [n1] runtime stats: 900 MiB RSS, 1509 goroutines, 421 MiB/144 MiB/777 MiB GO alloc/idle/total, 96 MiB/144 MiB CGO alloc/total, 154632.4 CGO/sec, 2206.9/216.0 %(u/s)time, 0.4 %gc (43x), 182 MiB/204 MiB (r/w)net -test-0001> I181130 22:14:47.400515 437 gossip/gossip.go:555 [n1] gossip status (ok, 3 nodes) +test-0001> I181130 22:14:34.828612 740 storage/store_rebalancer.go:277 [T1,n1,s1,store-rebalancer] load-based lease transfers successfully brought s1 down to 37128.65 qps (mean=29834.62, upperThreshold=37293.27) +test-0001> I181130 22:14:37.516378 441 server/status/runtime.go:465 [T1,n1] runtime stats: 900 MiB RSS, 1509 goroutines, 421 MiB/144 MiB/777 MiB GO alloc/idle/total, 96 MiB/144 MiB CGO alloc/total, 154632.4 CGO/sec, 2206.9/216.0 %(u/s)time, 0.4 %gc (43x), 182 MiB/204 MiB (r/w)net +test-0001> I181130 22:14:47.400515 437 gossip/gossip.go:555 [T1,n1] gossip status (ok, 3 nodes) gossip client (0/3 cur/max conns) gossip server (2/3 cur/max conns, infos 4077/2242 sent/received, bytes 1275332B/555352B sent/received) 2: ajwerner-test-0002:26257 (8m0s) 3: ajwerner-test-0003:26257 (8m0s) -test-0001> I181130 22:14:47.519324 441 server/status/runtime.go:465 [n1] runtime stats: 957 MiB RSS, 1690 goroutines, 420 MiB/173 MiB/777 MiB GO alloc/idle/total, 124 MiB/174 MiB CGO alloc/total, 143837.6 CGO/sec, 2245.9/218.3 %(u/s)time, 0.5 %gc (47x), 199 MiB/210 MiB (r/w)net -test-0002> I181130 22:14:49.706516 6152567 storage/split_queue.go:213 [n2,split,s2,r163/3:/Table/53/1/-36{84178…-35915…}] initiating a split based on load at key /Table/53/1/-3661595080111255049 -test-0002> I181130 22:14:49.706563 6152567 storage/replica_command.go:342 [n2,split,s2,r163/3:/Table/53/1/-36{84178…-35915…}] initiating a split of this range at key /Table/53/1/-3661595080111255049 [r586] -test-0002> I181130 22:14:49.732930 6153357 storage/split_queue.go:213 [n2,split,s2,r269/3:/Table/53/1/-81{56147…-10716…}] initiating a split based on load at key /Table/53/1/-8134885765915906309 -test-0002> I181130 22:14:49.732976 6153357 storage/replica_command.go:342 [n2,split,s2,r269/3:/Table/53/1/-81{56147…-10716…}] initiating a split of this range at key /Table/53/1/-8134885765915906309 [r587] -test-0002> I181130 22:14:50.203263 6163815 storage/split_queue.go:213 [n2,split,s2,r171/3:/Table/53/1/-87{94402…-45781…}] initiating a split based on load at key /Table/53/1/-8768249731886885702 -test-0002> I181130 22:14:50.203299 6163815 storage/replica_command.go:342 [n2,split,s2,r171/3:/Table/53/1/-87{94402…-45781…}] initiating a split of this range at key /Table/53/1/-8768249731886885702 [r588] -test-0001> I181130 22:14:57.522236 441 server/status/runtime.go:465 [n1] runtime stats: 986 MiB RSS, 1332 goroutines, 438 MiB/140 MiB/777 MiB GO alloc/idle/total, 151 MiB/203 MiB CGO alloc/total, 137663.6 CGO/sec, 2168.3/222.8 %(u/s)time, 0.4 %gc (45x), 192 MiB/203 MiB (r/w)net -test-0002> I181130 22:14:57.650774 499 server/status/runtime.go:465 [n2] runtime stats: 729 MiB RSS, 1127 goroutines, 416 MiB/91 MiB/584 MiB GO alloc/idle/total, 75 MiB/128 MiB CGO alloc/total, 111534.7 CGO/sec, 2013.0/232.3 %(u/s)time, 0.4 %gc (56x), 189 MiB/189 MiB (r/w)net -test-0002> I181130 22:15:05.892547 6507691 storage/split_queue.go:213 [n2,split,s2,r129/3:/Table/53/1/-{722633…-673989…}] initiating a split based on load at key /Table/53/1/-698671514117501959 -test-0002> I181130 22:15:05.892592 6507691 storage/replica_command.go:342 [n2,split,s2,r129/3:/Table/53/1/-{722633…-673989…}] initiating a split of this range at key /Table/53/1/-698671514117501959 [r589] -test-0001> I181130 22:15:07.525316 441 server/status/runtime.go:465 [n1] runtime stats: 952 MiB RSS, 1422 goroutines, 397 MiB/165 MiB/777 MiB GO alloc/idle/total, 112 MiB/164 MiB CGO alloc/total, 133359.9 CGO/sec, 2137.8/225.1 %(u/s)time, 0.4 %gc (43x), 187 MiB/198 MiB (r/w)net -test-0002> I181130 22:15:07.653821 499 server/status/runtime.go:465 [n2] runtime stats: 756 MiB RSS, 1127 goroutines, 338 MiB/113 MiB/584 MiB GO alloc/idle/total, 94 MiB/149 MiB CGO alloc/total, 108469.2 CGO/sec, 1964.7/227.0 %(u/s)time, 0.4 %gc (54x), 185 MiB/184 MiB (r/w)net +test-0001> I181130 22:14:47.519324 441 server/status/runtime.go:465 [T1,n1] runtime stats: 957 MiB RSS, 1690 goroutines, 420 MiB/173 MiB/777 MiB GO alloc/idle/total, 124 MiB/174 MiB CGO alloc/total, 143837.6 CGO/sec, 2245.9/218.3 %(u/s)time, 0.5 %gc (47x), 199 MiB/210 MiB (r/w)net +test-0002> I181130 22:14:49.706516 6152567 storage/split_queue.go:213 [T1,n2,split,s2,r163/3:/Table/53/1/-36{84178…-35915…}] initiating a split based on load at key /Table/53/1/-3661595080111255049 +test-0002> I181130 22:14:49.706563 6152567 storage/replica_command.go:342 [T1,n2,split,s2,r163/3:/Table/53/1/-36{84178…-35915…}] initiating a split of this range at key /Table/53/1/-3661595080111255049 [r586] +test-0002> I181130 22:14:49.732930 6153357 storage/split_queue.go:213 [T1,n2,split,s2,r269/3:/Table/53/1/-81{56147…-10716…}] initiating a split based on load at key /Table/53/1/-8134885765915906309 +test-0002> I181130 22:14:49.732976 6153357 storage/replica_command.go:342 [T1,n2,split,s2,r269/3:/Table/53/1/-81{56147…-10716…}] initiating a split of this range at key /Table/53/1/-8134885765915906309 [r587] +test-0002> I181130 22:14:50.203263 6163815 storage/split_queue.go:213 [T1,n2,split,s2,r171/3:/Table/53/1/-87{94402…-45781…}] initiating a split based on load at key /Table/53/1/-8768249731886885702 +test-0002> I181130 22:14:50.203299 6163815 storage/replica_command.go:342 [T1,n2,split,s2,r171/3:/Table/53/1/-87{94402…-45781…}] initiating a split of this range at key /Table/53/1/-8768249731886885702 [r588] +test-0001> I181130 22:14:57.522236 441 server/status/runtime.go:465 [T1,n1] runtime stats: 986 MiB RSS, 1332 goroutines, 438 MiB/140 MiB/777 MiB GO alloc/idle/total, 151 MiB/203 MiB CGO alloc/total, 137663.6 CGO/sec, 2168.3/222.8 %(u/s)time, 0.4 %gc (45x), 192 MiB/203 MiB (r/w)net +test-0002> I181130 22:14:57.650774 499 server/status/runtime.go:465 [T1,n2] runtime stats: 729 MiB RSS, 1127 goroutines, 416 MiB/91 MiB/584 MiB GO alloc/idle/total, 75 MiB/128 MiB CGO alloc/total, 111534.7 CGO/sec, 2013.0/232.3 %(u/s)time, 0.4 %gc (56x), 189 MiB/189 MiB (r/w)net +test-0002> I181130 22:15:05.892547 6507691 storage/split_queue.go:213 [T1,n2,split,s2,r129/3:/Table/53/1/-{722633…-673989…}] initiating a split based on load at key /Table/53/1/-698671514117501959 +test-0002> I181130 22:15:05.892592 6507691 storage/replica_command.go:342 [T1,n2,split,s2,r129/3:/Table/53/1/-{722633…-673989…}] initiating a split of this range at key /Table/53/1/-698671514117501959 [r589] +test-0001> I181130 22:15:07.525316 441 server/status/runtime.go:465 [T1,n1] runtime stats: 952 MiB RSS, 1422 goroutines, 397 MiB/165 MiB/777 MiB GO alloc/idle/total, 112 MiB/164 MiB CGO alloc/total, 133359.9 CGO/sec, 2137.8/225.1 %(u/s)time, 0.4 %gc (43x), 187 MiB/198 MiB (r/w)net +test-0002> I181130 22:15:07.653821 499 server/status/runtime.go:465 [T1,n2] runtime stats: 756 MiB RSS, 1127 goroutines, 338 MiB/113 MiB/584 MiB GO alloc/idle/total, 94 MiB/149 MiB CGO alloc/total, 108469.2 CGO/sec, 1964.7/227.0 %(u/s)time, 0.4 %gc (54x), 185 MiB/184 MiB (r/w)net diff --git a/pkg/cli/testdata/merge_logs_crdb-v1/results/1.filter-message b/pkg/cli/testdata/merge_logs_crdb-v1/results/1.filter-message index 401ace269349..f4a69646441c 100644 --- a/pkg/cli/testdata/merge_logs_crdb-v1/results/1.filter-message +++ b/pkg/cli/testdata/merge_logs_crdb-v1/results/1.filter-message @@ -1,4 +1,4 @@ -test-0001> I181130 22:14:47.400515 437 gossip/gossip.go:555 [n1] gossip status (ok, 3 nodes) +test-0001> I181130 22:14:47.400515 437 gossip/gossip.go:555 [T1,n1] gossip status (ok, 3 nodes) gossip client (0/3 cur/max conns) gossip server (2/3 cur/max conns, infos 4077/2242 sent/received, bytes 1275332B/555352B sent/received) 2: ajwerner-test-0002:26257 (8m0s) diff --git a/pkg/cli/testdata/merge_logs_crdb-v1/results/1.seek-past-end-of-file b/pkg/cli/testdata/merge_logs_crdb-v1/results/1.seek-past-end-of-file index b367d19e2f19..7e11e3c4252e 100644 --- a/pkg/cli/testdata/merge_logs_crdb-v1/results/1.seek-past-end-of-file +++ b/pkg/cli/testdata/merge_logs_crdb-v1/results/1.seek-past-end-of-file @@ -1 +1 @@ -test-0002> I181130 22:15:07.653821 499 server/status/runtime.go:465 [n2] runtime stats: 756 MiB RSS, 1127 goroutines, 338 MiB/113 MiB/584 MiB GO alloc/idle/total, 94 MiB/149 MiB CGO alloc/total, 108469.2 CGO/sec, 1964.7/227.0 %(u/s)time, 0.4 %gc (54x), 185 MiB/184 MiB (r/w)net +test-0002> I181130 22:15:07.653821 499 server/status/runtime.go:465 [T1,n2] runtime stats: 756 MiB RSS, 1127 goroutines, 338 MiB/113 MiB/584 MiB GO alloc/idle/total, 94 MiB/149 MiB CGO alloc/total, 108469.2 CGO/sec, 1964.7/227.0 %(u/s)time, 0.4 %gc (54x), 185 MiB/184 MiB (r/w)net diff --git a/pkg/cli/testdata/merge_logs_crdb-v1/results/2.multiple-files-from-node b/pkg/cli/testdata/merge_logs_crdb-v1/results/2.multiple-files-from-node index 586d6b74b71f..718b4422b147 100644 --- a/pkg/cli/testdata/merge_logs_crdb-v1/results/2.multiple-files-from-node +++ b/pkg/cli/testdata/merge_logs_crdb-v1/results/2.multiple-files-from-node @@ -1,20 +1,20 @@ -test-0001> I181130 22:14:34.828612 740 storage/store_rebalancer.go:277 [n1,s1,store-rebalancer] load-based lease transfers successfully brought s1 down to 37128.65 qps (mean=29834.62, upperThreshold=37293.27) -test-0001> I181130 22:14:37.516378 441 server/status/runtime.go:465 [n1] runtime stats: 900 MiB RSS, 1509 goroutines, 421 MiB/144 MiB/777 MiB GO alloc/idle/total, 96 MiB/144 MiB CGO alloc/total, 154632.4 CGO/sec, 2206.9/216.0 %(u/s)time, 0.4 %gc (43x), 182 MiB/204 MiB (r/w)net -test-0001> I181130 22:14:47.400515 437 gossip/gossip.go:555 [n1] gossip status (ok, 3 nodes) +test-0001> I181130 22:14:34.828612 740 storage/store_rebalancer.go:277 [T1,n1,s1,store-rebalancer] load-based lease transfers successfully brought s1 down to 37128.65 qps (mean=29834.62, upperThreshold=37293.27) +test-0001> I181130 22:14:37.516378 441 server/status/runtime.go:465 [T1,n1] runtime stats: 900 MiB RSS, 1509 goroutines, 421 MiB/144 MiB/777 MiB GO alloc/idle/total, 96 MiB/144 MiB CGO alloc/total, 154632.4 CGO/sec, 2206.9/216.0 %(u/s)time, 0.4 %gc (43x), 182 MiB/204 MiB (r/w)net +test-0001> I181130 22:14:47.400515 437 gossip/gossip.go:555 [T1,n1] gossip status (ok, 3 nodes) gossip client (0/3 cur/max conns) gossip server (2/3 cur/max conns, infos 4077/2242 sent/received, bytes 1275332B/555352B sent/received) 2: ajwerner-test-0002:26257 (8m0s) 3: ajwerner-test-0003:26257 (8m0s) -test-0001> I181130 22:14:47.519324 441 server/status/runtime.go:465 [n1] runtime stats: 957 MiB RSS, 1690 goroutines, 420 MiB/173 MiB/777 MiB GO alloc/idle/total, 124 MiB/174 MiB CGO alloc/total, 143837.6 CGO/sec, 2245.9/218.3 %(u/s)time, 0.5 %gc (47x), 199 MiB/210 MiB (r/w)net -test-0002> I181130 22:14:49.706516 6152567 storage/split_queue.go:213 [n2,split,s2,r163/3:/Table/53/1/-36{84178…-35915…}] initiating a split based on load at key /Table/53/1/-3661595080111255049 -test-0002> I181130 22:14:49.706563 6152567 storage/replica_command.go:342 [n2,split,s2,r163/3:/Table/53/1/-36{84178…-35915…}] initiating a split of this range at key /Table/53/1/-3661595080111255049 [r586] -test-0002> I181130 22:14:49.732930 6153357 storage/split_queue.go:213 [n2,split,s2,r269/3:/Table/53/1/-81{56147…-10716…}] initiating a split based on load at key /Table/53/1/-8134885765915906309 -test-0002> I181130 22:14:49.732976 6153357 storage/replica_command.go:342 [n2,split,s2,r269/3:/Table/53/1/-81{56147…-10716…}] initiating a split of this range at key /Table/53/1/-8134885765915906309 [r587] -test-0002> I181130 22:14:50.203263 6163815 storage/split_queue.go:213 [n2,split,s2,r171/3:/Table/53/1/-87{94402…-45781…}] initiating a split based on load at key /Table/53/1/-8768249731886885702 -test-0002> I181130 22:14:50.203299 6163815 storage/replica_command.go:342 [n2,split,s2,r171/3:/Table/53/1/-87{94402…-45781…}] initiating a split of this range at key /Table/53/1/-8768249731886885702 [r588] -test-0001> I181130 22:14:57.522236 441 server/status/runtime.go:465 [n1] runtime stats: 986 MiB RSS, 1332 goroutines, 438 MiB/140 MiB/777 MiB GO alloc/idle/total, 151 MiB/203 MiB CGO alloc/total, 137663.6 CGO/sec, 2168.3/222.8 %(u/s)time, 0.4 %gc (45x), 192 MiB/203 MiB (r/w)net -test-0002> I181130 22:14:57.650774 499 server/status/runtime.go:465 [n2] runtime stats: 729 MiB RSS, 1127 goroutines, 416 MiB/91 MiB/584 MiB GO alloc/idle/total, 75 MiB/128 MiB CGO alloc/total, 111534.7 CGO/sec, 2013.0/232.3 %(u/s)time, 0.4 %gc (56x), 189 MiB/189 MiB (r/w)net -test-0002> I181130 22:15:05.892547 6507691 storage/split_queue.go:213 [n2,split,s2,r129/3:/Table/53/1/-{722633…-673989…}] initiating a split based on load at key /Table/53/1/-698671514117501959 -test-0002> I181130 22:15:05.892592 6507691 storage/replica_command.go:342 [n2,split,s2,r129/3:/Table/53/1/-{722633…-673989…}] initiating a split of this range at key /Table/53/1/-698671514117501959 [r589] -test-0001> I181130 22:15:07.525316 441 server/status/runtime.go:465 [n1] runtime stats: 952 MiB RSS, 1422 goroutines, 397 MiB/165 MiB/777 MiB GO alloc/idle/total, 112 MiB/164 MiB CGO alloc/total, 133359.9 CGO/sec, 2137.8/225.1 %(u/s)time, 0.4 %gc (43x), 187 MiB/198 MiB (r/w)net -test-0002> I181130 22:15:07.653821 499 server/status/runtime.go:465 [n2] runtime stats: 756 MiB RSS, 1127 goroutines, 338 MiB/113 MiB/584 MiB GO alloc/idle/total, 94 MiB/149 MiB CGO alloc/total, 108469.2 CGO/sec, 1964.7/227.0 %(u/s)time, 0.4 %gc (54x), 185 MiB/184 MiB (r/w)net +test-0001> I181130 22:14:47.519324 441 server/status/runtime.go:465 [T1,n1] runtime stats: 957 MiB RSS, 1690 goroutines, 420 MiB/173 MiB/777 MiB GO alloc/idle/total, 124 MiB/174 MiB CGO alloc/total, 143837.6 CGO/sec, 2245.9/218.3 %(u/s)time, 0.5 %gc (47x), 199 MiB/210 MiB (r/w)net +test-0002> I181130 22:14:49.706516 6152567 storage/split_queue.go:213 [T1,n2,split,s2,r163/3:/Table/53/1/-36{84178…-35915…}] initiating a split based on load at key /Table/53/1/-3661595080111255049 +test-0002> I181130 22:14:49.706563 6152567 storage/replica_command.go:342 [T1,n2,split,s2,r163/3:/Table/53/1/-36{84178…-35915…}] initiating a split of this range at key /Table/53/1/-3661595080111255049 [r586] +test-0002> I181130 22:14:49.732930 6153357 storage/split_queue.go:213 [T1,n2,split,s2,r269/3:/Table/53/1/-81{56147…-10716…}] initiating a split based on load at key /Table/53/1/-8134885765915906309 +test-0002> I181130 22:14:49.732976 6153357 storage/replica_command.go:342 [T1,n2,split,s2,r269/3:/Table/53/1/-81{56147…-10716…}] initiating a split of this range at key /Table/53/1/-8134885765915906309 [r587] +test-0002> I181130 22:14:50.203263 6163815 storage/split_queue.go:213 [T1,n2,split,s2,r171/3:/Table/53/1/-87{94402…-45781…}] initiating a split based on load at key /Table/53/1/-8768249731886885702 +test-0002> I181130 22:14:50.203299 6163815 storage/replica_command.go:342 [T1,n2,split,s2,r171/3:/Table/53/1/-87{94402…-45781…}] initiating a split of this range at key /Table/53/1/-8768249731886885702 [r588] +test-0001> I181130 22:14:57.522236 441 server/status/runtime.go:465 [T1,n1] runtime stats: 986 MiB RSS, 1332 goroutines, 438 MiB/140 MiB/777 MiB GO alloc/idle/total, 151 MiB/203 MiB CGO alloc/total, 137663.6 CGO/sec, 2168.3/222.8 %(u/s)time, 0.4 %gc (45x), 192 MiB/203 MiB (r/w)net +test-0002> I181130 22:14:57.650774 499 server/status/runtime.go:465 [T1,n2] runtime stats: 729 MiB RSS, 1127 goroutines, 416 MiB/91 MiB/584 MiB GO alloc/idle/total, 75 MiB/128 MiB CGO alloc/total, 111534.7 CGO/sec, 2013.0/232.3 %(u/s)time, 0.4 %gc (56x), 189 MiB/189 MiB (r/w)net +test-0002> I181130 22:15:05.892547 6507691 storage/split_queue.go:213 [T1,n2,split,s2,r129/3:/Table/53/1/-{722633…-673989…}] initiating a split based on load at key /Table/53/1/-698671514117501959 +test-0002> I181130 22:15:05.892592 6507691 storage/replica_command.go:342 [T1,n2,split,s2,r129/3:/Table/53/1/-{722633…-673989…}] initiating a split of this range at key /Table/53/1/-698671514117501959 [r589] +test-0001> I181130 22:15:07.525316 441 server/status/runtime.go:465 [T1,n1] runtime stats: 952 MiB RSS, 1422 goroutines, 397 MiB/165 MiB/777 MiB GO alloc/idle/total, 112 MiB/164 MiB CGO alloc/total, 133359.9 CGO/sec, 2137.8/225.1 %(u/s)time, 0.4 %gc (43x), 187 MiB/198 MiB (r/w)net +test-0002> I181130 22:15:07.653821 499 server/status/runtime.go:465 [T1,n2] runtime stats: 756 MiB RSS, 1127 goroutines, 338 MiB/113 MiB/584 MiB GO alloc/idle/total, 94 MiB/149 MiB CGO alloc/total, 108469.2 CGO/sec, 1964.7/227.0 %(u/s)time, 0.4 %gc (54x), 185 MiB/184 MiB (r/w)net diff --git a/pkg/cli/testdata/merge_logs_crdb-v1/results/2.remove-duplicates b/pkg/cli/testdata/merge_logs_crdb-v1/results/2.remove-duplicates index f8c19a121b58..28ba5776da4f 100644 --- a/pkg/cli/testdata/merge_logs_crdb-v1/results/2.remove-duplicates +++ b/pkg/cli/testdata/merge_logs_crdb-v1/results/2.remove-duplicates @@ -1,2 +1,2 @@ -test-0001> I181130 22:15:07.525316 441 server/status/runtime.go:465 [n1] runtime stats: 952 MiB RSS, 1422 goroutines, 397 MiB/165 MiB/777 MiB GO alloc/idle/total, 112 MiB/164 MiB CGO alloc/total, 133359.9 CGO/sec, 2137.8/225.1 %(u/s)time, 0.4 %gc (43x), 187 MiB/198 MiB (r/w)net -test-0002> I181130 22:15:07.653821 499 server/status/runtime.go:465 [n2] runtime stats: 756 MiB RSS, 1127 goroutines, 338 MiB/113 MiB/584 MiB GO alloc/idle/total, 94 MiB/149 MiB CGO alloc/total, 108469.2 CGO/sec, 1964.7/227.0 %(u/s)time, 0.4 %gc (54x), 185 MiB/184 MiB (r/w)net +test-0001> I181130 22:15:07.525316 441 server/status/runtime.go:465 [T1,n1] runtime stats: 952 MiB RSS, 1422 goroutines, 397 MiB/165 MiB/777 MiB GO alloc/idle/total, 112 MiB/164 MiB CGO alloc/total, 133359.9 CGO/sec, 2137.8/225.1 %(u/s)time, 0.4 %gc (43x), 187 MiB/198 MiB (r/w)net +test-0002> I181130 22:15:07.653821 499 server/status/runtime.go:465 [T1,n2] runtime stats: 756 MiB RSS, 1127 goroutines, 338 MiB/113 MiB/584 MiB GO alloc/idle/total, 94 MiB/149 MiB CGO alloc/total, 108469.2 CGO/sec, 1964.7/227.0 %(u/s)time, 0.4 %gc (54x), 185 MiB/184 MiB (r/w)net diff --git a/pkg/cli/testdata/merge_logs_crdb-v1/results/2.skip-file b/pkg/cli/testdata/merge_logs_crdb-v1/results/2.skip-file index f8c19a121b58..28ba5776da4f 100644 --- a/pkg/cli/testdata/merge_logs_crdb-v1/results/2.skip-file +++ b/pkg/cli/testdata/merge_logs_crdb-v1/results/2.skip-file @@ -1,2 +1,2 @@ -test-0001> I181130 22:15:07.525316 441 server/status/runtime.go:465 [n1] runtime stats: 952 MiB RSS, 1422 goroutines, 397 MiB/165 MiB/777 MiB GO alloc/idle/total, 112 MiB/164 MiB CGO alloc/total, 133359.9 CGO/sec, 2137.8/225.1 %(u/s)time, 0.4 %gc (43x), 187 MiB/198 MiB (r/w)net -test-0002> I181130 22:15:07.653821 499 server/status/runtime.go:465 [n2] runtime stats: 756 MiB RSS, 1127 goroutines, 338 MiB/113 MiB/584 MiB GO alloc/idle/total, 94 MiB/149 MiB CGO alloc/total, 108469.2 CGO/sec, 1964.7/227.0 %(u/s)time, 0.4 %gc (54x), 185 MiB/184 MiB (r/w)net +test-0001> I181130 22:15:07.525316 441 server/status/runtime.go:465 [T1,n1] runtime stats: 952 MiB RSS, 1422 goroutines, 397 MiB/165 MiB/777 MiB GO alloc/idle/total, 112 MiB/164 MiB CGO alloc/total, 133359.9 CGO/sec, 2137.8/225.1 %(u/s)time, 0.4 %gc (43x), 187 MiB/198 MiB (r/w)net +test-0002> I181130 22:15:07.653821 499 server/status/runtime.go:465 [T1,n2] runtime stats: 756 MiB RSS, 1127 goroutines, 338 MiB/113 MiB/584 MiB GO alloc/idle/total, 94 MiB/149 MiB CGO alloc/total, 108469.2 CGO/sec, 1964.7/227.0 %(u/s)time, 0.4 %gc (54x), 185 MiB/184 MiB (r/w)net diff --git a/pkg/cli/testdata/merge_logs_crdb-v1/results/2.walk-directory b/pkg/cli/testdata/merge_logs_crdb-v1/results/2.walk-directory index 586d6b74b71f..718b4422b147 100644 --- a/pkg/cli/testdata/merge_logs_crdb-v1/results/2.walk-directory +++ b/pkg/cli/testdata/merge_logs_crdb-v1/results/2.walk-directory @@ -1,20 +1,20 @@ -test-0001> I181130 22:14:34.828612 740 storage/store_rebalancer.go:277 [n1,s1,store-rebalancer] load-based lease transfers successfully brought s1 down to 37128.65 qps (mean=29834.62, upperThreshold=37293.27) -test-0001> I181130 22:14:37.516378 441 server/status/runtime.go:465 [n1] runtime stats: 900 MiB RSS, 1509 goroutines, 421 MiB/144 MiB/777 MiB GO alloc/idle/total, 96 MiB/144 MiB CGO alloc/total, 154632.4 CGO/sec, 2206.9/216.0 %(u/s)time, 0.4 %gc (43x), 182 MiB/204 MiB (r/w)net -test-0001> I181130 22:14:47.400515 437 gossip/gossip.go:555 [n1] gossip status (ok, 3 nodes) +test-0001> I181130 22:14:34.828612 740 storage/store_rebalancer.go:277 [T1,n1,s1,store-rebalancer] load-based lease transfers successfully brought s1 down to 37128.65 qps (mean=29834.62, upperThreshold=37293.27) +test-0001> I181130 22:14:37.516378 441 server/status/runtime.go:465 [T1,n1] runtime stats: 900 MiB RSS, 1509 goroutines, 421 MiB/144 MiB/777 MiB GO alloc/idle/total, 96 MiB/144 MiB CGO alloc/total, 154632.4 CGO/sec, 2206.9/216.0 %(u/s)time, 0.4 %gc (43x), 182 MiB/204 MiB (r/w)net +test-0001> I181130 22:14:47.400515 437 gossip/gossip.go:555 [T1,n1] gossip status (ok, 3 nodes) gossip client (0/3 cur/max conns) gossip server (2/3 cur/max conns, infos 4077/2242 sent/received, bytes 1275332B/555352B sent/received) 2: ajwerner-test-0002:26257 (8m0s) 3: ajwerner-test-0003:26257 (8m0s) -test-0001> I181130 22:14:47.519324 441 server/status/runtime.go:465 [n1] runtime stats: 957 MiB RSS, 1690 goroutines, 420 MiB/173 MiB/777 MiB GO alloc/idle/total, 124 MiB/174 MiB CGO alloc/total, 143837.6 CGO/sec, 2245.9/218.3 %(u/s)time, 0.5 %gc (47x), 199 MiB/210 MiB (r/w)net -test-0002> I181130 22:14:49.706516 6152567 storage/split_queue.go:213 [n2,split,s2,r163/3:/Table/53/1/-36{84178…-35915…}] initiating a split based on load at key /Table/53/1/-3661595080111255049 -test-0002> I181130 22:14:49.706563 6152567 storage/replica_command.go:342 [n2,split,s2,r163/3:/Table/53/1/-36{84178…-35915…}] initiating a split of this range at key /Table/53/1/-3661595080111255049 [r586] -test-0002> I181130 22:14:49.732930 6153357 storage/split_queue.go:213 [n2,split,s2,r269/3:/Table/53/1/-81{56147…-10716…}] initiating a split based on load at key /Table/53/1/-8134885765915906309 -test-0002> I181130 22:14:49.732976 6153357 storage/replica_command.go:342 [n2,split,s2,r269/3:/Table/53/1/-81{56147…-10716…}] initiating a split of this range at key /Table/53/1/-8134885765915906309 [r587] -test-0002> I181130 22:14:50.203263 6163815 storage/split_queue.go:213 [n2,split,s2,r171/3:/Table/53/1/-87{94402…-45781…}] initiating a split based on load at key /Table/53/1/-8768249731886885702 -test-0002> I181130 22:14:50.203299 6163815 storage/replica_command.go:342 [n2,split,s2,r171/3:/Table/53/1/-87{94402…-45781…}] initiating a split of this range at key /Table/53/1/-8768249731886885702 [r588] -test-0001> I181130 22:14:57.522236 441 server/status/runtime.go:465 [n1] runtime stats: 986 MiB RSS, 1332 goroutines, 438 MiB/140 MiB/777 MiB GO alloc/idle/total, 151 MiB/203 MiB CGO alloc/total, 137663.6 CGO/sec, 2168.3/222.8 %(u/s)time, 0.4 %gc (45x), 192 MiB/203 MiB (r/w)net -test-0002> I181130 22:14:57.650774 499 server/status/runtime.go:465 [n2] runtime stats: 729 MiB RSS, 1127 goroutines, 416 MiB/91 MiB/584 MiB GO alloc/idle/total, 75 MiB/128 MiB CGO alloc/total, 111534.7 CGO/sec, 2013.0/232.3 %(u/s)time, 0.4 %gc (56x), 189 MiB/189 MiB (r/w)net -test-0002> I181130 22:15:05.892547 6507691 storage/split_queue.go:213 [n2,split,s2,r129/3:/Table/53/1/-{722633…-673989…}] initiating a split based on load at key /Table/53/1/-698671514117501959 -test-0002> I181130 22:15:05.892592 6507691 storage/replica_command.go:342 [n2,split,s2,r129/3:/Table/53/1/-{722633…-673989…}] initiating a split of this range at key /Table/53/1/-698671514117501959 [r589] -test-0001> I181130 22:15:07.525316 441 server/status/runtime.go:465 [n1] runtime stats: 952 MiB RSS, 1422 goroutines, 397 MiB/165 MiB/777 MiB GO alloc/idle/total, 112 MiB/164 MiB CGO alloc/total, 133359.9 CGO/sec, 2137.8/225.1 %(u/s)time, 0.4 %gc (43x), 187 MiB/198 MiB (r/w)net -test-0002> I181130 22:15:07.653821 499 server/status/runtime.go:465 [n2] runtime stats: 756 MiB RSS, 1127 goroutines, 338 MiB/113 MiB/584 MiB GO alloc/idle/total, 94 MiB/149 MiB CGO alloc/total, 108469.2 CGO/sec, 1964.7/227.0 %(u/s)time, 0.4 %gc (54x), 185 MiB/184 MiB (r/w)net +test-0001> I181130 22:14:47.519324 441 server/status/runtime.go:465 [T1,n1] runtime stats: 957 MiB RSS, 1690 goroutines, 420 MiB/173 MiB/777 MiB GO alloc/idle/total, 124 MiB/174 MiB CGO alloc/total, 143837.6 CGO/sec, 2245.9/218.3 %(u/s)time, 0.5 %gc (47x), 199 MiB/210 MiB (r/w)net +test-0002> I181130 22:14:49.706516 6152567 storage/split_queue.go:213 [T1,n2,split,s2,r163/3:/Table/53/1/-36{84178…-35915…}] initiating a split based on load at key /Table/53/1/-3661595080111255049 +test-0002> I181130 22:14:49.706563 6152567 storage/replica_command.go:342 [T1,n2,split,s2,r163/3:/Table/53/1/-36{84178…-35915…}] initiating a split of this range at key /Table/53/1/-3661595080111255049 [r586] +test-0002> I181130 22:14:49.732930 6153357 storage/split_queue.go:213 [T1,n2,split,s2,r269/3:/Table/53/1/-81{56147…-10716…}] initiating a split based on load at key /Table/53/1/-8134885765915906309 +test-0002> I181130 22:14:49.732976 6153357 storage/replica_command.go:342 [T1,n2,split,s2,r269/3:/Table/53/1/-81{56147…-10716…}] initiating a split of this range at key /Table/53/1/-8134885765915906309 [r587] +test-0002> I181130 22:14:50.203263 6163815 storage/split_queue.go:213 [T1,n2,split,s2,r171/3:/Table/53/1/-87{94402…-45781…}] initiating a split based on load at key /Table/53/1/-8768249731886885702 +test-0002> I181130 22:14:50.203299 6163815 storage/replica_command.go:342 [T1,n2,split,s2,r171/3:/Table/53/1/-87{94402…-45781…}] initiating a split of this range at key /Table/53/1/-8768249731886885702 [r588] +test-0001> I181130 22:14:57.522236 441 server/status/runtime.go:465 [T1,n1] runtime stats: 986 MiB RSS, 1332 goroutines, 438 MiB/140 MiB/777 MiB GO alloc/idle/total, 151 MiB/203 MiB CGO alloc/total, 137663.6 CGO/sec, 2168.3/222.8 %(u/s)time, 0.4 %gc (45x), 192 MiB/203 MiB (r/w)net +test-0002> I181130 22:14:57.650774 499 server/status/runtime.go:465 [T1,n2] runtime stats: 729 MiB RSS, 1127 goroutines, 416 MiB/91 MiB/584 MiB GO alloc/idle/total, 75 MiB/128 MiB CGO alloc/total, 111534.7 CGO/sec, 2013.0/232.3 %(u/s)time, 0.4 %gc (56x), 189 MiB/189 MiB (r/w)net +test-0002> I181130 22:15:05.892547 6507691 storage/split_queue.go:213 [T1,n2,split,s2,r129/3:/Table/53/1/-{722633…-673989…}] initiating a split based on load at key /Table/53/1/-698671514117501959 +test-0002> I181130 22:15:05.892592 6507691 storage/replica_command.go:342 [T1,n2,split,s2,r129/3:/Table/53/1/-{722633…-673989…}] initiating a split of this range at key /Table/53/1/-698671514117501959 [r589] +test-0001> I181130 22:15:07.525316 441 server/status/runtime.go:465 [T1,n1] runtime stats: 952 MiB RSS, 1422 goroutines, 397 MiB/165 MiB/777 MiB GO alloc/idle/total, 112 MiB/164 MiB CGO alloc/total, 133359.9 CGO/sec, 2137.8/225.1 %(u/s)time, 0.4 %gc (43x), 187 MiB/198 MiB (r/w)net +test-0002> I181130 22:15:07.653821 499 server/status/runtime.go:465 [T1,n2] runtime stats: 756 MiB RSS, 1127 goroutines, 338 MiB/113 MiB/584 MiB GO alloc/idle/total, 94 MiB/149 MiB CGO alloc/total, 108469.2 CGO/sec, 1964.7/227.0 %(u/s)time, 0.4 %gc (54x), 185 MiB/184 MiB (r/w)net diff --git a/pkg/cli/testdata/merge_logs_crdb-v1/results/3.non-standard b/pkg/cli/testdata/merge_logs_crdb-v1/results/3.non-standard index a1005a6d8dca..aeb88c5ac4d5 100644 --- a/pkg/cli/testdata/merge_logs_crdb-v1/results/3.non-standard +++ b/pkg/cli/testdata/merge_logs_crdb-v1/results/3.non-standard @@ -1,20 +1,20 @@ -I181130 22:14:34.828612 740 storage/store_rebalancer.go:277 [n1,s1,store-rebalancer] load-based lease transfers successfully brought s1 down to 37128.65 qps (mean=29834.62, upperThreshold=37293.27) -I181130 22:14:37.516378 441 server/status/runtime.go:465 [n1] runtime stats: 900 MiB RSS, 1509 goroutines, 421 MiB/144 MiB/777 MiB GO alloc/idle/total, 96 MiB/144 MiB CGO alloc/total, 154632.4 CGO/sec, 2206.9/216.0 %(u/s)time, 0.4 %gc (43x), 182 MiB/204 MiB (r/w)net -I181130 22:14:47.400515 437 gossip/gossip.go:555 [n1] gossip status (ok, 3 nodes) +I181130 22:14:34.828612 740 storage/store_rebalancer.go:277 [T1,n1,s1,store-rebalancer] load-based lease transfers successfully brought s1 down to 37128.65 qps (mean=29834.62, upperThreshold=37293.27) +I181130 22:14:37.516378 441 server/status/runtime.go:465 [T1,n1] runtime stats: 900 MiB RSS, 1509 goroutines, 421 MiB/144 MiB/777 MiB GO alloc/idle/total, 96 MiB/144 MiB CGO alloc/total, 154632.4 CGO/sec, 2206.9/216.0 %(u/s)time, 0.4 %gc (43x), 182 MiB/204 MiB (r/w)net +I181130 22:14:47.400515 437 gossip/gossip.go:555 [T1,n1] gossip status (ok, 3 nodes) gossip client (0/3 cur/max conns) gossip server (2/3 cur/max conns, infos 4077/2242 sent/received, bytes 1275332B/555352B sent/received) 2: ajwerner-test-0002:26257 (8m0s) 3: ajwerner-test-0003:26257 (8m0s) -I181130 22:14:47.519324 441 server/status/runtime.go:465 [n1] runtime stats: 957 MiB RSS, 1690 goroutines, 420 MiB/173 MiB/777 MiB GO alloc/idle/total, 124 MiB/174 MiB CGO alloc/total, 143837.6 CGO/sec, 2245.9/218.3 %(u/s)time, 0.5 %gc (47x), 199 MiB/210 MiB (r/w)net -I181130 22:14:49.706516 6152567 storage/split_queue.go:213 [n2,split,s2,r163/3:/Table/53/1/-36{84178…-35915…}] initiating a split based on load at key /Table/53/1/-3661595080111255049 -I181130 22:14:49.706563 6152567 storage/replica_command.go:342 [n2,split,s2,r163/3:/Table/53/1/-36{84178…-35915…}] initiating a split of this range at key /Table/53/1/-3661595080111255049 [r586] -I181130 22:14:49.732930 6153357 storage/split_queue.go:213 [n2,split,s2,r269/3:/Table/53/1/-81{56147…-10716…}] initiating a split based on load at key /Table/53/1/-8134885765915906309 -I181130 22:14:49.732976 6153357 storage/replica_command.go:342 [n2,split,s2,r269/3:/Table/53/1/-81{56147…-10716…}] initiating a split of this range at key /Table/53/1/-8134885765915906309 [r587] -I181130 22:14:50.203263 6163815 storage/split_queue.go:213 [n2,split,s2,r171/3:/Table/53/1/-87{94402…-45781…}] initiating a split based on load at key /Table/53/1/-8768249731886885702 -I181130 22:14:50.203299 6163815 storage/replica_command.go:342 [n2,split,s2,r171/3:/Table/53/1/-87{94402…-45781…}] initiating a split of this range at key /Table/53/1/-8768249731886885702 [r588] -I181130 22:14:57.522236 441 server/status/runtime.go:465 [n1] runtime stats: 986 MiB RSS, 1332 goroutines, 438 MiB/140 MiB/777 MiB GO alloc/idle/total, 151 MiB/203 MiB CGO alloc/total, 137663.6 CGO/sec, 2168.3/222.8 %(u/s)time, 0.4 %gc (45x), 192 MiB/203 MiB (r/w)net -I181130 22:14:57.650774 499 server/status/runtime.go:465 [n2] runtime stats: 729 MiB RSS, 1127 goroutines, 416 MiB/91 MiB/584 MiB GO alloc/idle/total, 75 MiB/128 MiB CGO alloc/total, 111534.7 CGO/sec, 2013.0/232.3 %(u/s)time, 0.4 %gc (56x), 189 MiB/189 MiB (r/w)net -I181130 22:15:05.892547 6507691 storage/split_queue.go:213 [n2,split,s2,r129/3:/Table/53/1/-{722633…-673989…}] initiating a split based on load at key /Table/53/1/-698671514117501959 -I181130 22:15:05.892592 6507691 storage/replica_command.go:342 [n2,split,s2,r129/3:/Table/53/1/-{722633…-673989…}] initiating a split of this range at key /Table/53/1/-698671514117501959 [r589] -I181130 22:15:07.525316 441 server/status/runtime.go:465 [n1] runtime stats: 952 MiB RSS, 1422 goroutines, 397 MiB/165 MiB/777 MiB GO alloc/idle/total, 112 MiB/164 MiB CGO alloc/total, 133359.9 CGO/sec, 2137.8/225.1 %(u/s)time, 0.4 %gc (43x), 187 MiB/198 MiB (r/w)net -I181130 22:15:07.653821 499 server/status/runtime.go:465 [n2] runtime stats: 756 MiB RSS, 1127 goroutines, 338 MiB/113 MiB/584 MiB GO alloc/idle/total, 94 MiB/149 MiB CGO alloc/total, 108469.2 CGO/sec, 1964.7/227.0 %(u/s)time, 0.4 %gc (54x), 185 MiB/184 MiB (r/w)net +I181130 22:14:47.519324 441 server/status/runtime.go:465 [T1,n1] runtime stats: 957 MiB RSS, 1690 goroutines, 420 MiB/173 MiB/777 MiB GO alloc/idle/total, 124 MiB/174 MiB CGO alloc/total, 143837.6 CGO/sec, 2245.9/218.3 %(u/s)time, 0.5 %gc (47x), 199 MiB/210 MiB (r/w)net +I181130 22:14:49.706516 6152567 storage/split_queue.go:213 [T1,n2,split,s2,r163/3:/Table/53/1/-36{84178…-35915…}] initiating a split based on load at key /Table/53/1/-3661595080111255049 +I181130 22:14:49.706563 6152567 storage/replica_command.go:342 [T1,n2,split,s2,r163/3:/Table/53/1/-36{84178…-35915…}] initiating a split of this range at key /Table/53/1/-3661595080111255049 [r586] +I181130 22:14:49.732930 6153357 storage/split_queue.go:213 [T1,n2,split,s2,r269/3:/Table/53/1/-81{56147…-10716…}] initiating a split based on load at key /Table/53/1/-8134885765915906309 +I181130 22:14:49.732976 6153357 storage/replica_command.go:342 [T1,n2,split,s2,r269/3:/Table/53/1/-81{56147…-10716…}] initiating a split of this range at key /Table/53/1/-8134885765915906309 [r587] +I181130 22:14:50.203263 6163815 storage/split_queue.go:213 [T1,n2,split,s2,r171/3:/Table/53/1/-87{94402…-45781…}] initiating a split based on load at key /Table/53/1/-8768249731886885702 +I181130 22:14:50.203299 6163815 storage/replica_command.go:342 [T1,n2,split,s2,r171/3:/Table/53/1/-87{94402…-45781…}] initiating a split of this range at key /Table/53/1/-8768249731886885702 [r588] +I181130 22:14:57.522236 441 server/status/runtime.go:465 [T1,n1] runtime stats: 986 MiB RSS, 1332 goroutines, 438 MiB/140 MiB/777 MiB GO alloc/idle/total, 151 MiB/203 MiB CGO alloc/total, 137663.6 CGO/sec, 2168.3/222.8 %(u/s)time, 0.4 %gc (45x), 192 MiB/203 MiB (r/w)net +I181130 22:14:57.650774 499 server/status/runtime.go:465 [T1,n2] runtime stats: 729 MiB RSS, 1127 goroutines, 416 MiB/91 MiB/584 MiB GO alloc/idle/total, 75 MiB/128 MiB CGO alloc/total, 111534.7 CGO/sec, 2013.0/232.3 %(u/s)time, 0.4 %gc (56x), 189 MiB/189 MiB (r/w)net +I181130 22:15:05.892547 6507691 storage/split_queue.go:213 [T1,n2,split,s2,r129/3:/Table/53/1/-{722633…-673989…}] initiating a split based on load at key /Table/53/1/-698671514117501959 +I181130 22:15:05.892592 6507691 storage/replica_command.go:342 [T1,n2,split,s2,r129/3:/Table/53/1/-{722633…-673989…}] initiating a split of this range at key /Table/53/1/-698671514117501959 [r589] +I181130 22:15:07.525316 441 server/status/runtime.go:465 [T1,n1] runtime stats: 952 MiB RSS, 1422 goroutines, 397 MiB/165 MiB/777 MiB GO alloc/idle/total, 112 MiB/164 MiB CGO alloc/total, 133359.9 CGO/sec, 2137.8/225.1 %(u/s)time, 0.4 %gc (43x), 187 MiB/198 MiB (r/w)net +I181130 22:15:07.653821 499 server/status/runtime.go:465 [T1,n2] runtime stats: 756 MiB RSS, 1127 goroutines, 338 MiB/113 MiB/584 MiB GO alloc/idle/total, 94 MiB/149 MiB CGO alloc/total, 108469.2 CGO/sec, 1964.7/227.0 %(u/s)time, 0.4 %gc (54x), 185 MiB/184 MiB (r/w)net diff --git a/pkg/cli/testdata/merge_logs_crdb-v1/results/4.filter b/pkg/cli/testdata/merge_logs_crdb-v1/results/4.filter index acd2c58d4b4f..e908b7b6232c 100644 --- a/pkg/cli/testdata/merge_logs_crdb-v1/results/4.filter +++ b/pkg/cli/testdata/merge_logs_crdb-v1/results/4.filter @@ -1,2 +1,2 @@ -> E190412 10:06:00.645112 195432 storage/queue.go:866 [n1,replicate,s1,r161/2:/Table/84/{1/5/7-2}] no removable replicas from range that needs a removal: [2*:27, 3:0] -> E190412 10:06:00.818605 195938 storage/queue.go:866 [n1,replicate,s1,r159/2:/Table/84/1/{4-5/6}] no removable replicas from range that needs a removal: [2*:27, 3:0] +> E190412 10:06:00.645112 195432 storage/queue.go:866 [T1,n1,replicate,s1,r161/2:/Table/84/{1/5/7-2}] no removable replicas from range that needs a removal: [2*:27, 3:0] +> E190412 10:06:00.818605 195938 storage/queue.go:866 [T1,n1,replicate,s1,r159/2:/Table/84/1/{4-5/6}] no removable replicas from range that needs a removal: [2*:27, 3:0] diff --git a/pkg/cli/testdata/merge_logs_crdb-v1/results/5.redact-off-redactable-off b/pkg/cli/testdata/merge_logs_crdb-v1/results/5.redact-off-redactable-off index 8412e23e7b8f..ec1fb98ce872 100644 --- a/pkg/cli/testdata/merge_logs_crdb-v1/results/5.redact-off-redactable-off +++ b/pkg/cli/testdata/merge_logs_crdb-v1/results/5.redact-off-redactable-off @@ -1,2 +1,2 @@ -> I190412 10:06:00.490104 183717 server/server.go:1423 safe unsafe -> I190412 10:06:00.490104 183717 server/server.go:1424 unknownsafe +> I190412 10:06:00.490104 183717 server/server.go:1423 [T1] safe unsafe +> I190412 10:06:00.490104 183717 server/server.go:1424 [T1] unknownsafe diff --git a/pkg/cli/testdata/merge_logs_crdb-v1/results/5.redact-off-redactable-on b/pkg/cli/testdata/merge_logs_crdb-v1/results/5.redact-off-redactable-on index 6ae8be145614..1b72e52d1f78 100644 --- a/pkg/cli/testdata/merge_logs_crdb-v1/results/5.redact-off-redactable-on +++ b/pkg/cli/testdata/merge_logs_crdb-v1/results/5.redact-off-redactable-on @@ -1,2 +1,2 @@ -> I190412 10:06:00.490104 183717 server/server.go:1423 ⋮ safe ‹unsafe› -> I190412 10:06:00.490104 183717 server/server.go:1424 ⋮ ‹unknownsafe› +> I190412 10:06:00.490104 183717 server/server.go:1423 ⋮ [T1] safe ‹unsafe› +> I190412 10:06:00.490104 183717 server/server.go:1424 ⋮ [T1] ‹unknownsafe› diff --git a/pkg/cli/testdata/merge_logs_crdb-v1/results/5.redact-on-redactable-off b/pkg/cli/testdata/merge_logs_crdb-v1/results/5.redact-on-redactable-off index 42e7505a3fed..acc01ec7086a 100644 --- a/pkg/cli/testdata/merge_logs_crdb-v1/results/5.redact-on-redactable-off +++ b/pkg/cli/testdata/merge_logs_crdb-v1/results/5.redact-on-redactable-off @@ -1,2 +1,2 @@ -> I190412 10:06:00.490104 183717 server/server.go:1423 safe × -> I190412 10:06:00.490104 183717 server/server.go:1424 × +> I190412 10:06:00.490104 183717 server/server.go:1423 [T1] safe × +> I190412 10:06:00.490104 183717 server/server.go:1424 [T1] × diff --git a/pkg/cli/testdata/merge_logs_crdb-v1/results/5.redact-on-redactable-on b/pkg/cli/testdata/merge_logs_crdb-v1/results/5.redact-on-redactable-on index 5547f1c32955..498a0b05e6d9 100644 --- a/pkg/cli/testdata/merge_logs_crdb-v1/results/5.redact-on-redactable-on +++ b/pkg/cli/testdata/merge_logs_crdb-v1/results/5.redact-on-redactable-on @@ -1,2 +1,2 @@ -> I190412 10:06:00.490104 183717 server/server.go:1423 ⋮ safe ‹×› -> I190412 10:06:00.490104 183717 server/server.go:1424 ⋮ ‹×› +> I190412 10:06:00.490104 183717 server/server.go:1423 ⋮ [T1] safe ‹×› +> I190412 10:06:00.490104 183717 server/server.go:1424 ⋮ [T1] ‹×› diff --git a/pkg/cli/testdata/merge_logs_crdb-v2/5/redactable.log b/pkg/cli/testdata/merge_logs_crdb-v2/5/redactable.log index 50c18fed7ea7..fd194da96cd1 100644 --- a/pkg/cli/testdata/merge_logs_crdb-v2/5/redactable.log +++ b/pkg/cli/testdata/merge_logs_crdb-v2/5/redactable.log @@ -1,2 +1,2 @@ -I190412 10:06:00.490104 183717 server/server.go:1423 ⋮ [-] safe ‹unsafe› -I190412 10:06:00.490104 183717 server/server.go:1424 [-] unknownsafe +I190412 10:06:00.490104 183717 server/server.go:1423 ⋮ [T1] safe ‹unsafe› +I190412 10:06:00.490104 183717 server/server.go:1424 [T1] unknownsafe diff --git a/pkg/cli/testdata/merge_logs_crdb-v2/results/1.all b/pkg/cli/testdata/merge_logs_crdb-v2/results/1.all index 586d6b74b71f..718b4422b147 100644 --- a/pkg/cli/testdata/merge_logs_crdb-v2/results/1.all +++ b/pkg/cli/testdata/merge_logs_crdb-v2/results/1.all @@ -1,20 +1,20 @@ -test-0001> I181130 22:14:34.828612 740 storage/store_rebalancer.go:277 [n1,s1,store-rebalancer] load-based lease transfers successfully brought s1 down to 37128.65 qps (mean=29834.62, upperThreshold=37293.27) -test-0001> I181130 22:14:37.516378 441 server/status/runtime.go:465 [n1] runtime stats: 900 MiB RSS, 1509 goroutines, 421 MiB/144 MiB/777 MiB GO alloc/idle/total, 96 MiB/144 MiB CGO alloc/total, 154632.4 CGO/sec, 2206.9/216.0 %(u/s)time, 0.4 %gc (43x), 182 MiB/204 MiB (r/w)net -test-0001> I181130 22:14:47.400515 437 gossip/gossip.go:555 [n1] gossip status (ok, 3 nodes) +test-0001> I181130 22:14:34.828612 740 storage/store_rebalancer.go:277 [T1,n1,s1,store-rebalancer] load-based lease transfers successfully brought s1 down to 37128.65 qps (mean=29834.62, upperThreshold=37293.27) +test-0001> I181130 22:14:37.516378 441 server/status/runtime.go:465 [T1,n1] runtime stats: 900 MiB RSS, 1509 goroutines, 421 MiB/144 MiB/777 MiB GO alloc/idle/total, 96 MiB/144 MiB CGO alloc/total, 154632.4 CGO/sec, 2206.9/216.0 %(u/s)time, 0.4 %gc (43x), 182 MiB/204 MiB (r/w)net +test-0001> I181130 22:14:47.400515 437 gossip/gossip.go:555 [T1,n1] gossip status (ok, 3 nodes) gossip client (0/3 cur/max conns) gossip server (2/3 cur/max conns, infos 4077/2242 sent/received, bytes 1275332B/555352B sent/received) 2: ajwerner-test-0002:26257 (8m0s) 3: ajwerner-test-0003:26257 (8m0s) -test-0001> I181130 22:14:47.519324 441 server/status/runtime.go:465 [n1] runtime stats: 957 MiB RSS, 1690 goroutines, 420 MiB/173 MiB/777 MiB GO alloc/idle/total, 124 MiB/174 MiB CGO alloc/total, 143837.6 CGO/sec, 2245.9/218.3 %(u/s)time, 0.5 %gc (47x), 199 MiB/210 MiB (r/w)net -test-0002> I181130 22:14:49.706516 6152567 storage/split_queue.go:213 [n2,split,s2,r163/3:/Table/53/1/-36{84178…-35915…}] initiating a split based on load at key /Table/53/1/-3661595080111255049 -test-0002> I181130 22:14:49.706563 6152567 storage/replica_command.go:342 [n2,split,s2,r163/3:/Table/53/1/-36{84178…-35915…}] initiating a split of this range at key /Table/53/1/-3661595080111255049 [r586] -test-0002> I181130 22:14:49.732930 6153357 storage/split_queue.go:213 [n2,split,s2,r269/3:/Table/53/1/-81{56147…-10716…}] initiating a split based on load at key /Table/53/1/-8134885765915906309 -test-0002> I181130 22:14:49.732976 6153357 storage/replica_command.go:342 [n2,split,s2,r269/3:/Table/53/1/-81{56147…-10716…}] initiating a split of this range at key /Table/53/1/-8134885765915906309 [r587] -test-0002> I181130 22:14:50.203263 6163815 storage/split_queue.go:213 [n2,split,s2,r171/3:/Table/53/1/-87{94402…-45781…}] initiating a split based on load at key /Table/53/1/-8768249731886885702 -test-0002> I181130 22:14:50.203299 6163815 storage/replica_command.go:342 [n2,split,s2,r171/3:/Table/53/1/-87{94402…-45781…}] initiating a split of this range at key /Table/53/1/-8768249731886885702 [r588] -test-0001> I181130 22:14:57.522236 441 server/status/runtime.go:465 [n1] runtime stats: 986 MiB RSS, 1332 goroutines, 438 MiB/140 MiB/777 MiB GO alloc/idle/total, 151 MiB/203 MiB CGO alloc/total, 137663.6 CGO/sec, 2168.3/222.8 %(u/s)time, 0.4 %gc (45x), 192 MiB/203 MiB (r/w)net -test-0002> I181130 22:14:57.650774 499 server/status/runtime.go:465 [n2] runtime stats: 729 MiB RSS, 1127 goroutines, 416 MiB/91 MiB/584 MiB GO alloc/idle/total, 75 MiB/128 MiB CGO alloc/total, 111534.7 CGO/sec, 2013.0/232.3 %(u/s)time, 0.4 %gc (56x), 189 MiB/189 MiB (r/w)net -test-0002> I181130 22:15:05.892547 6507691 storage/split_queue.go:213 [n2,split,s2,r129/3:/Table/53/1/-{722633…-673989…}] initiating a split based on load at key /Table/53/1/-698671514117501959 -test-0002> I181130 22:15:05.892592 6507691 storage/replica_command.go:342 [n2,split,s2,r129/3:/Table/53/1/-{722633…-673989…}] initiating a split of this range at key /Table/53/1/-698671514117501959 [r589] -test-0001> I181130 22:15:07.525316 441 server/status/runtime.go:465 [n1] runtime stats: 952 MiB RSS, 1422 goroutines, 397 MiB/165 MiB/777 MiB GO alloc/idle/total, 112 MiB/164 MiB CGO alloc/total, 133359.9 CGO/sec, 2137.8/225.1 %(u/s)time, 0.4 %gc (43x), 187 MiB/198 MiB (r/w)net -test-0002> I181130 22:15:07.653821 499 server/status/runtime.go:465 [n2] runtime stats: 756 MiB RSS, 1127 goroutines, 338 MiB/113 MiB/584 MiB GO alloc/idle/total, 94 MiB/149 MiB CGO alloc/total, 108469.2 CGO/sec, 1964.7/227.0 %(u/s)time, 0.4 %gc (54x), 185 MiB/184 MiB (r/w)net +test-0001> I181130 22:14:47.519324 441 server/status/runtime.go:465 [T1,n1] runtime stats: 957 MiB RSS, 1690 goroutines, 420 MiB/173 MiB/777 MiB GO alloc/idle/total, 124 MiB/174 MiB CGO alloc/total, 143837.6 CGO/sec, 2245.9/218.3 %(u/s)time, 0.5 %gc (47x), 199 MiB/210 MiB (r/w)net +test-0002> I181130 22:14:49.706516 6152567 storage/split_queue.go:213 [T1,n2,split,s2,r163/3:/Table/53/1/-36{84178…-35915…}] initiating a split based on load at key /Table/53/1/-3661595080111255049 +test-0002> I181130 22:14:49.706563 6152567 storage/replica_command.go:342 [T1,n2,split,s2,r163/3:/Table/53/1/-36{84178…-35915…}] initiating a split of this range at key /Table/53/1/-3661595080111255049 [r586] +test-0002> I181130 22:14:49.732930 6153357 storage/split_queue.go:213 [T1,n2,split,s2,r269/3:/Table/53/1/-81{56147…-10716…}] initiating a split based on load at key /Table/53/1/-8134885765915906309 +test-0002> I181130 22:14:49.732976 6153357 storage/replica_command.go:342 [T1,n2,split,s2,r269/3:/Table/53/1/-81{56147…-10716…}] initiating a split of this range at key /Table/53/1/-8134885765915906309 [r587] +test-0002> I181130 22:14:50.203263 6163815 storage/split_queue.go:213 [T1,n2,split,s2,r171/3:/Table/53/1/-87{94402…-45781…}] initiating a split based on load at key /Table/53/1/-8768249731886885702 +test-0002> I181130 22:14:50.203299 6163815 storage/replica_command.go:342 [T1,n2,split,s2,r171/3:/Table/53/1/-87{94402…-45781…}] initiating a split of this range at key /Table/53/1/-8768249731886885702 [r588] +test-0001> I181130 22:14:57.522236 441 server/status/runtime.go:465 [T1,n1] runtime stats: 986 MiB RSS, 1332 goroutines, 438 MiB/140 MiB/777 MiB GO alloc/idle/total, 151 MiB/203 MiB CGO alloc/total, 137663.6 CGO/sec, 2168.3/222.8 %(u/s)time, 0.4 %gc (45x), 192 MiB/203 MiB (r/w)net +test-0002> I181130 22:14:57.650774 499 server/status/runtime.go:465 [T1,n2] runtime stats: 729 MiB RSS, 1127 goroutines, 416 MiB/91 MiB/584 MiB GO alloc/idle/total, 75 MiB/128 MiB CGO alloc/total, 111534.7 CGO/sec, 2013.0/232.3 %(u/s)time, 0.4 %gc (56x), 189 MiB/189 MiB (r/w)net +test-0002> I181130 22:15:05.892547 6507691 storage/split_queue.go:213 [T1,n2,split,s2,r129/3:/Table/53/1/-{722633…-673989…}] initiating a split based on load at key /Table/53/1/-698671514117501959 +test-0002> I181130 22:15:05.892592 6507691 storage/replica_command.go:342 [T1,n2,split,s2,r129/3:/Table/53/1/-{722633…-673989…}] initiating a split of this range at key /Table/53/1/-698671514117501959 [r589] +test-0001> I181130 22:15:07.525316 441 server/status/runtime.go:465 [T1,n1] runtime stats: 952 MiB RSS, 1422 goroutines, 397 MiB/165 MiB/777 MiB GO alloc/idle/total, 112 MiB/164 MiB CGO alloc/total, 133359.9 CGO/sec, 2137.8/225.1 %(u/s)time, 0.4 %gc (43x), 187 MiB/198 MiB (r/w)net +test-0002> I181130 22:15:07.653821 499 server/status/runtime.go:465 [T1,n2] runtime stats: 756 MiB RSS, 1127 goroutines, 338 MiB/113 MiB/584 MiB GO alloc/idle/total, 94 MiB/149 MiB CGO alloc/total, 108469.2 CGO/sec, 1964.7/227.0 %(u/s)time, 0.4 %gc (54x), 185 MiB/184 MiB (r/w)net diff --git a/pkg/cli/testdata/merge_logs_crdb-v2/results/1.filter-message b/pkg/cli/testdata/merge_logs_crdb-v2/results/1.filter-message index 401ace269349..f4a69646441c 100644 --- a/pkg/cli/testdata/merge_logs_crdb-v2/results/1.filter-message +++ b/pkg/cli/testdata/merge_logs_crdb-v2/results/1.filter-message @@ -1,4 +1,4 @@ -test-0001> I181130 22:14:47.400515 437 gossip/gossip.go:555 [n1] gossip status (ok, 3 nodes) +test-0001> I181130 22:14:47.400515 437 gossip/gossip.go:555 [T1,n1] gossip status (ok, 3 nodes) gossip client (0/3 cur/max conns) gossip server (2/3 cur/max conns, infos 4077/2242 sent/received, bytes 1275332B/555352B sent/received) 2: ajwerner-test-0002:26257 (8m0s) diff --git a/pkg/cli/testdata/merge_logs_crdb-v2/results/1.seek-past-end-of-file b/pkg/cli/testdata/merge_logs_crdb-v2/results/1.seek-past-end-of-file index b367d19e2f19..7e11e3c4252e 100644 --- a/pkg/cli/testdata/merge_logs_crdb-v2/results/1.seek-past-end-of-file +++ b/pkg/cli/testdata/merge_logs_crdb-v2/results/1.seek-past-end-of-file @@ -1 +1 @@ -test-0002> I181130 22:15:07.653821 499 server/status/runtime.go:465 [n2] runtime stats: 756 MiB RSS, 1127 goroutines, 338 MiB/113 MiB/584 MiB GO alloc/idle/total, 94 MiB/149 MiB CGO alloc/total, 108469.2 CGO/sec, 1964.7/227.0 %(u/s)time, 0.4 %gc (54x), 185 MiB/184 MiB (r/w)net +test-0002> I181130 22:15:07.653821 499 server/status/runtime.go:465 [T1,n2] runtime stats: 756 MiB RSS, 1127 goroutines, 338 MiB/113 MiB/584 MiB GO alloc/idle/total, 94 MiB/149 MiB CGO alloc/total, 108469.2 CGO/sec, 1964.7/227.0 %(u/s)time, 0.4 %gc (54x), 185 MiB/184 MiB (r/w)net diff --git a/pkg/cli/testdata/merge_logs_crdb-v2/results/2.multiple-files-from-node b/pkg/cli/testdata/merge_logs_crdb-v2/results/2.multiple-files-from-node index 586d6b74b71f..718b4422b147 100644 --- a/pkg/cli/testdata/merge_logs_crdb-v2/results/2.multiple-files-from-node +++ b/pkg/cli/testdata/merge_logs_crdb-v2/results/2.multiple-files-from-node @@ -1,20 +1,20 @@ -test-0001> I181130 22:14:34.828612 740 storage/store_rebalancer.go:277 [n1,s1,store-rebalancer] load-based lease transfers successfully brought s1 down to 37128.65 qps (mean=29834.62, upperThreshold=37293.27) -test-0001> I181130 22:14:37.516378 441 server/status/runtime.go:465 [n1] runtime stats: 900 MiB RSS, 1509 goroutines, 421 MiB/144 MiB/777 MiB GO alloc/idle/total, 96 MiB/144 MiB CGO alloc/total, 154632.4 CGO/sec, 2206.9/216.0 %(u/s)time, 0.4 %gc (43x), 182 MiB/204 MiB (r/w)net -test-0001> I181130 22:14:47.400515 437 gossip/gossip.go:555 [n1] gossip status (ok, 3 nodes) +test-0001> I181130 22:14:34.828612 740 storage/store_rebalancer.go:277 [T1,n1,s1,store-rebalancer] load-based lease transfers successfully brought s1 down to 37128.65 qps (mean=29834.62, upperThreshold=37293.27) +test-0001> I181130 22:14:37.516378 441 server/status/runtime.go:465 [T1,n1] runtime stats: 900 MiB RSS, 1509 goroutines, 421 MiB/144 MiB/777 MiB GO alloc/idle/total, 96 MiB/144 MiB CGO alloc/total, 154632.4 CGO/sec, 2206.9/216.0 %(u/s)time, 0.4 %gc (43x), 182 MiB/204 MiB (r/w)net +test-0001> I181130 22:14:47.400515 437 gossip/gossip.go:555 [T1,n1] gossip status (ok, 3 nodes) gossip client (0/3 cur/max conns) gossip server (2/3 cur/max conns, infos 4077/2242 sent/received, bytes 1275332B/555352B sent/received) 2: ajwerner-test-0002:26257 (8m0s) 3: ajwerner-test-0003:26257 (8m0s) -test-0001> I181130 22:14:47.519324 441 server/status/runtime.go:465 [n1] runtime stats: 957 MiB RSS, 1690 goroutines, 420 MiB/173 MiB/777 MiB GO alloc/idle/total, 124 MiB/174 MiB CGO alloc/total, 143837.6 CGO/sec, 2245.9/218.3 %(u/s)time, 0.5 %gc (47x), 199 MiB/210 MiB (r/w)net -test-0002> I181130 22:14:49.706516 6152567 storage/split_queue.go:213 [n2,split,s2,r163/3:/Table/53/1/-36{84178…-35915…}] initiating a split based on load at key /Table/53/1/-3661595080111255049 -test-0002> I181130 22:14:49.706563 6152567 storage/replica_command.go:342 [n2,split,s2,r163/3:/Table/53/1/-36{84178…-35915…}] initiating a split of this range at key /Table/53/1/-3661595080111255049 [r586] -test-0002> I181130 22:14:49.732930 6153357 storage/split_queue.go:213 [n2,split,s2,r269/3:/Table/53/1/-81{56147…-10716…}] initiating a split based on load at key /Table/53/1/-8134885765915906309 -test-0002> I181130 22:14:49.732976 6153357 storage/replica_command.go:342 [n2,split,s2,r269/3:/Table/53/1/-81{56147…-10716…}] initiating a split of this range at key /Table/53/1/-8134885765915906309 [r587] -test-0002> I181130 22:14:50.203263 6163815 storage/split_queue.go:213 [n2,split,s2,r171/3:/Table/53/1/-87{94402…-45781…}] initiating a split based on load at key /Table/53/1/-8768249731886885702 -test-0002> I181130 22:14:50.203299 6163815 storage/replica_command.go:342 [n2,split,s2,r171/3:/Table/53/1/-87{94402…-45781…}] initiating a split of this range at key /Table/53/1/-8768249731886885702 [r588] -test-0001> I181130 22:14:57.522236 441 server/status/runtime.go:465 [n1] runtime stats: 986 MiB RSS, 1332 goroutines, 438 MiB/140 MiB/777 MiB GO alloc/idle/total, 151 MiB/203 MiB CGO alloc/total, 137663.6 CGO/sec, 2168.3/222.8 %(u/s)time, 0.4 %gc (45x), 192 MiB/203 MiB (r/w)net -test-0002> I181130 22:14:57.650774 499 server/status/runtime.go:465 [n2] runtime stats: 729 MiB RSS, 1127 goroutines, 416 MiB/91 MiB/584 MiB GO alloc/idle/total, 75 MiB/128 MiB CGO alloc/total, 111534.7 CGO/sec, 2013.0/232.3 %(u/s)time, 0.4 %gc (56x), 189 MiB/189 MiB (r/w)net -test-0002> I181130 22:15:05.892547 6507691 storage/split_queue.go:213 [n2,split,s2,r129/3:/Table/53/1/-{722633…-673989…}] initiating a split based on load at key /Table/53/1/-698671514117501959 -test-0002> I181130 22:15:05.892592 6507691 storage/replica_command.go:342 [n2,split,s2,r129/3:/Table/53/1/-{722633…-673989…}] initiating a split of this range at key /Table/53/1/-698671514117501959 [r589] -test-0001> I181130 22:15:07.525316 441 server/status/runtime.go:465 [n1] runtime stats: 952 MiB RSS, 1422 goroutines, 397 MiB/165 MiB/777 MiB GO alloc/idle/total, 112 MiB/164 MiB CGO alloc/total, 133359.9 CGO/sec, 2137.8/225.1 %(u/s)time, 0.4 %gc (43x), 187 MiB/198 MiB (r/w)net -test-0002> I181130 22:15:07.653821 499 server/status/runtime.go:465 [n2] runtime stats: 756 MiB RSS, 1127 goroutines, 338 MiB/113 MiB/584 MiB GO alloc/idle/total, 94 MiB/149 MiB CGO alloc/total, 108469.2 CGO/sec, 1964.7/227.0 %(u/s)time, 0.4 %gc (54x), 185 MiB/184 MiB (r/w)net +test-0001> I181130 22:14:47.519324 441 server/status/runtime.go:465 [T1,n1] runtime stats: 957 MiB RSS, 1690 goroutines, 420 MiB/173 MiB/777 MiB GO alloc/idle/total, 124 MiB/174 MiB CGO alloc/total, 143837.6 CGO/sec, 2245.9/218.3 %(u/s)time, 0.5 %gc (47x), 199 MiB/210 MiB (r/w)net +test-0002> I181130 22:14:49.706516 6152567 storage/split_queue.go:213 [T1,n2,split,s2,r163/3:/Table/53/1/-36{84178…-35915…}] initiating a split based on load at key /Table/53/1/-3661595080111255049 +test-0002> I181130 22:14:49.706563 6152567 storage/replica_command.go:342 [T1,n2,split,s2,r163/3:/Table/53/1/-36{84178…-35915…}] initiating a split of this range at key /Table/53/1/-3661595080111255049 [r586] +test-0002> I181130 22:14:49.732930 6153357 storage/split_queue.go:213 [T1,n2,split,s2,r269/3:/Table/53/1/-81{56147…-10716…}] initiating a split based on load at key /Table/53/1/-8134885765915906309 +test-0002> I181130 22:14:49.732976 6153357 storage/replica_command.go:342 [T1,n2,split,s2,r269/3:/Table/53/1/-81{56147…-10716…}] initiating a split of this range at key /Table/53/1/-8134885765915906309 [r587] +test-0002> I181130 22:14:50.203263 6163815 storage/split_queue.go:213 [T1,n2,split,s2,r171/3:/Table/53/1/-87{94402…-45781…}] initiating a split based on load at key /Table/53/1/-8768249731886885702 +test-0002> I181130 22:14:50.203299 6163815 storage/replica_command.go:342 [T1,n2,split,s2,r171/3:/Table/53/1/-87{94402…-45781…}] initiating a split of this range at key /Table/53/1/-8768249731886885702 [r588] +test-0001> I181130 22:14:57.522236 441 server/status/runtime.go:465 [T1,n1] runtime stats: 986 MiB RSS, 1332 goroutines, 438 MiB/140 MiB/777 MiB GO alloc/idle/total, 151 MiB/203 MiB CGO alloc/total, 137663.6 CGO/sec, 2168.3/222.8 %(u/s)time, 0.4 %gc (45x), 192 MiB/203 MiB (r/w)net +test-0002> I181130 22:14:57.650774 499 server/status/runtime.go:465 [T1,n2] runtime stats: 729 MiB RSS, 1127 goroutines, 416 MiB/91 MiB/584 MiB GO alloc/idle/total, 75 MiB/128 MiB CGO alloc/total, 111534.7 CGO/sec, 2013.0/232.3 %(u/s)time, 0.4 %gc (56x), 189 MiB/189 MiB (r/w)net +test-0002> I181130 22:15:05.892547 6507691 storage/split_queue.go:213 [T1,n2,split,s2,r129/3:/Table/53/1/-{722633…-673989…}] initiating a split based on load at key /Table/53/1/-698671514117501959 +test-0002> I181130 22:15:05.892592 6507691 storage/replica_command.go:342 [T1,n2,split,s2,r129/3:/Table/53/1/-{722633…-673989…}] initiating a split of this range at key /Table/53/1/-698671514117501959 [r589] +test-0001> I181130 22:15:07.525316 441 server/status/runtime.go:465 [T1,n1] runtime stats: 952 MiB RSS, 1422 goroutines, 397 MiB/165 MiB/777 MiB GO alloc/idle/total, 112 MiB/164 MiB CGO alloc/total, 133359.9 CGO/sec, 2137.8/225.1 %(u/s)time, 0.4 %gc (43x), 187 MiB/198 MiB (r/w)net +test-0002> I181130 22:15:07.653821 499 server/status/runtime.go:465 [T1,n2] runtime stats: 756 MiB RSS, 1127 goroutines, 338 MiB/113 MiB/584 MiB GO alloc/idle/total, 94 MiB/149 MiB CGO alloc/total, 108469.2 CGO/sec, 1964.7/227.0 %(u/s)time, 0.4 %gc (54x), 185 MiB/184 MiB (r/w)net diff --git a/pkg/cli/testdata/merge_logs_crdb-v2/results/2.remove-duplicates b/pkg/cli/testdata/merge_logs_crdb-v2/results/2.remove-duplicates index f8c19a121b58..28ba5776da4f 100644 --- a/pkg/cli/testdata/merge_logs_crdb-v2/results/2.remove-duplicates +++ b/pkg/cli/testdata/merge_logs_crdb-v2/results/2.remove-duplicates @@ -1,2 +1,2 @@ -test-0001> I181130 22:15:07.525316 441 server/status/runtime.go:465 [n1] runtime stats: 952 MiB RSS, 1422 goroutines, 397 MiB/165 MiB/777 MiB GO alloc/idle/total, 112 MiB/164 MiB CGO alloc/total, 133359.9 CGO/sec, 2137.8/225.1 %(u/s)time, 0.4 %gc (43x), 187 MiB/198 MiB (r/w)net -test-0002> I181130 22:15:07.653821 499 server/status/runtime.go:465 [n2] runtime stats: 756 MiB RSS, 1127 goroutines, 338 MiB/113 MiB/584 MiB GO alloc/idle/total, 94 MiB/149 MiB CGO alloc/total, 108469.2 CGO/sec, 1964.7/227.0 %(u/s)time, 0.4 %gc (54x), 185 MiB/184 MiB (r/w)net +test-0001> I181130 22:15:07.525316 441 server/status/runtime.go:465 [T1,n1] runtime stats: 952 MiB RSS, 1422 goroutines, 397 MiB/165 MiB/777 MiB GO alloc/idle/total, 112 MiB/164 MiB CGO alloc/total, 133359.9 CGO/sec, 2137.8/225.1 %(u/s)time, 0.4 %gc (43x), 187 MiB/198 MiB (r/w)net +test-0002> I181130 22:15:07.653821 499 server/status/runtime.go:465 [T1,n2] runtime stats: 756 MiB RSS, 1127 goroutines, 338 MiB/113 MiB/584 MiB GO alloc/idle/total, 94 MiB/149 MiB CGO alloc/total, 108469.2 CGO/sec, 1964.7/227.0 %(u/s)time, 0.4 %gc (54x), 185 MiB/184 MiB (r/w)net diff --git a/pkg/cli/testdata/merge_logs_crdb-v2/results/2.skip-file b/pkg/cli/testdata/merge_logs_crdb-v2/results/2.skip-file index f8c19a121b58..28ba5776da4f 100644 --- a/pkg/cli/testdata/merge_logs_crdb-v2/results/2.skip-file +++ b/pkg/cli/testdata/merge_logs_crdb-v2/results/2.skip-file @@ -1,2 +1,2 @@ -test-0001> I181130 22:15:07.525316 441 server/status/runtime.go:465 [n1] runtime stats: 952 MiB RSS, 1422 goroutines, 397 MiB/165 MiB/777 MiB GO alloc/idle/total, 112 MiB/164 MiB CGO alloc/total, 133359.9 CGO/sec, 2137.8/225.1 %(u/s)time, 0.4 %gc (43x), 187 MiB/198 MiB (r/w)net -test-0002> I181130 22:15:07.653821 499 server/status/runtime.go:465 [n2] runtime stats: 756 MiB RSS, 1127 goroutines, 338 MiB/113 MiB/584 MiB GO alloc/idle/total, 94 MiB/149 MiB CGO alloc/total, 108469.2 CGO/sec, 1964.7/227.0 %(u/s)time, 0.4 %gc (54x), 185 MiB/184 MiB (r/w)net +test-0001> I181130 22:15:07.525316 441 server/status/runtime.go:465 [T1,n1] runtime stats: 952 MiB RSS, 1422 goroutines, 397 MiB/165 MiB/777 MiB GO alloc/idle/total, 112 MiB/164 MiB CGO alloc/total, 133359.9 CGO/sec, 2137.8/225.1 %(u/s)time, 0.4 %gc (43x), 187 MiB/198 MiB (r/w)net +test-0002> I181130 22:15:07.653821 499 server/status/runtime.go:465 [T1,n2] runtime stats: 756 MiB RSS, 1127 goroutines, 338 MiB/113 MiB/584 MiB GO alloc/idle/total, 94 MiB/149 MiB CGO alloc/total, 108469.2 CGO/sec, 1964.7/227.0 %(u/s)time, 0.4 %gc (54x), 185 MiB/184 MiB (r/w)net diff --git a/pkg/cli/testdata/merge_logs_crdb-v2/results/2.walk-directory b/pkg/cli/testdata/merge_logs_crdb-v2/results/2.walk-directory index 586d6b74b71f..718b4422b147 100644 --- a/pkg/cli/testdata/merge_logs_crdb-v2/results/2.walk-directory +++ b/pkg/cli/testdata/merge_logs_crdb-v2/results/2.walk-directory @@ -1,20 +1,20 @@ -test-0001> I181130 22:14:34.828612 740 storage/store_rebalancer.go:277 [n1,s1,store-rebalancer] load-based lease transfers successfully brought s1 down to 37128.65 qps (mean=29834.62, upperThreshold=37293.27) -test-0001> I181130 22:14:37.516378 441 server/status/runtime.go:465 [n1] runtime stats: 900 MiB RSS, 1509 goroutines, 421 MiB/144 MiB/777 MiB GO alloc/idle/total, 96 MiB/144 MiB CGO alloc/total, 154632.4 CGO/sec, 2206.9/216.0 %(u/s)time, 0.4 %gc (43x), 182 MiB/204 MiB (r/w)net -test-0001> I181130 22:14:47.400515 437 gossip/gossip.go:555 [n1] gossip status (ok, 3 nodes) +test-0001> I181130 22:14:34.828612 740 storage/store_rebalancer.go:277 [T1,n1,s1,store-rebalancer] load-based lease transfers successfully brought s1 down to 37128.65 qps (mean=29834.62, upperThreshold=37293.27) +test-0001> I181130 22:14:37.516378 441 server/status/runtime.go:465 [T1,n1] runtime stats: 900 MiB RSS, 1509 goroutines, 421 MiB/144 MiB/777 MiB GO alloc/idle/total, 96 MiB/144 MiB CGO alloc/total, 154632.4 CGO/sec, 2206.9/216.0 %(u/s)time, 0.4 %gc (43x), 182 MiB/204 MiB (r/w)net +test-0001> I181130 22:14:47.400515 437 gossip/gossip.go:555 [T1,n1] gossip status (ok, 3 nodes) gossip client (0/3 cur/max conns) gossip server (2/3 cur/max conns, infos 4077/2242 sent/received, bytes 1275332B/555352B sent/received) 2: ajwerner-test-0002:26257 (8m0s) 3: ajwerner-test-0003:26257 (8m0s) -test-0001> I181130 22:14:47.519324 441 server/status/runtime.go:465 [n1] runtime stats: 957 MiB RSS, 1690 goroutines, 420 MiB/173 MiB/777 MiB GO alloc/idle/total, 124 MiB/174 MiB CGO alloc/total, 143837.6 CGO/sec, 2245.9/218.3 %(u/s)time, 0.5 %gc (47x), 199 MiB/210 MiB (r/w)net -test-0002> I181130 22:14:49.706516 6152567 storage/split_queue.go:213 [n2,split,s2,r163/3:/Table/53/1/-36{84178…-35915…}] initiating a split based on load at key /Table/53/1/-3661595080111255049 -test-0002> I181130 22:14:49.706563 6152567 storage/replica_command.go:342 [n2,split,s2,r163/3:/Table/53/1/-36{84178…-35915…}] initiating a split of this range at key /Table/53/1/-3661595080111255049 [r586] -test-0002> I181130 22:14:49.732930 6153357 storage/split_queue.go:213 [n2,split,s2,r269/3:/Table/53/1/-81{56147…-10716…}] initiating a split based on load at key /Table/53/1/-8134885765915906309 -test-0002> I181130 22:14:49.732976 6153357 storage/replica_command.go:342 [n2,split,s2,r269/3:/Table/53/1/-81{56147…-10716…}] initiating a split of this range at key /Table/53/1/-8134885765915906309 [r587] -test-0002> I181130 22:14:50.203263 6163815 storage/split_queue.go:213 [n2,split,s2,r171/3:/Table/53/1/-87{94402…-45781…}] initiating a split based on load at key /Table/53/1/-8768249731886885702 -test-0002> I181130 22:14:50.203299 6163815 storage/replica_command.go:342 [n2,split,s2,r171/3:/Table/53/1/-87{94402…-45781…}] initiating a split of this range at key /Table/53/1/-8768249731886885702 [r588] -test-0001> I181130 22:14:57.522236 441 server/status/runtime.go:465 [n1] runtime stats: 986 MiB RSS, 1332 goroutines, 438 MiB/140 MiB/777 MiB GO alloc/idle/total, 151 MiB/203 MiB CGO alloc/total, 137663.6 CGO/sec, 2168.3/222.8 %(u/s)time, 0.4 %gc (45x), 192 MiB/203 MiB (r/w)net -test-0002> I181130 22:14:57.650774 499 server/status/runtime.go:465 [n2] runtime stats: 729 MiB RSS, 1127 goroutines, 416 MiB/91 MiB/584 MiB GO alloc/idle/total, 75 MiB/128 MiB CGO alloc/total, 111534.7 CGO/sec, 2013.0/232.3 %(u/s)time, 0.4 %gc (56x), 189 MiB/189 MiB (r/w)net -test-0002> I181130 22:15:05.892547 6507691 storage/split_queue.go:213 [n2,split,s2,r129/3:/Table/53/1/-{722633…-673989…}] initiating a split based on load at key /Table/53/1/-698671514117501959 -test-0002> I181130 22:15:05.892592 6507691 storage/replica_command.go:342 [n2,split,s2,r129/3:/Table/53/1/-{722633…-673989…}] initiating a split of this range at key /Table/53/1/-698671514117501959 [r589] -test-0001> I181130 22:15:07.525316 441 server/status/runtime.go:465 [n1] runtime stats: 952 MiB RSS, 1422 goroutines, 397 MiB/165 MiB/777 MiB GO alloc/idle/total, 112 MiB/164 MiB CGO alloc/total, 133359.9 CGO/sec, 2137.8/225.1 %(u/s)time, 0.4 %gc (43x), 187 MiB/198 MiB (r/w)net -test-0002> I181130 22:15:07.653821 499 server/status/runtime.go:465 [n2] runtime stats: 756 MiB RSS, 1127 goroutines, 338 MiB/113 MiB/584 MiB GO alloc/idle/total, 94 MiB/149 MiB CGO alloc/total, 108469.2 CGO/sec, 1964.7/227.0 %(u/s)time, 0.4 %gc (54x), 185 MiB/184 MiB (r/w)net +test-0001> I181130 22:14:47.519324 441 server/status/runtime.go:465 [T1,n1] runtime stats: 957 MiB RSS, 1690 goroutines, 420 MiB/173 MiB/777 MiB GO alloc/idle/total, 124 MiB/174 MiB CGO alloc/total, 143837.6 CGO/sec, 2245.9/218.3 %(u/s)time, 0.5 %gc (47x), 199 MiB/210 MiB (r/w)net +test-0002> I181130 22:14:49.706516 6152567 storage/split_queue.go:213 [T1,n2,split,s2,r163/3:/Table/53/1/-36{84178…-35915…}] initiating a split based on load at key /Table/53/1/-3661595080111255049 +test-0002> I181130 22:14:49.706563 6152567 storage/replica_command.go:342 [T1,n2,split,s2,r163/3:/Table/53/1/-36{84178…-35915…}] initiating a split of this range at key /Table/53/1/-3661595080111255049 [r586] +test-0002> I181130 22:14:49.732930 6153357 storage/split_queue.go:213 [T1,n2,split,s2,r269/3:/Table/53/1/-81{56147…-10716…}] initiating a split based on load at key /Table/53/1/-8134885765915906309 +test-0002> I181130 22:14:49.732976 6153357 storage/replica_command.go:342 [T1,n2,split,s2,r269/3:/Table/53/1/-81{56147…-10716…}] initiating a split of this range at key /Table/53/1/-8134885765915906309 [r587] +test-0002> I181130 22:14:50.203263 6163815 storage/split_queue.go:213 [T1,n2,split,s2,r171/3:/Table/53/1/-87{94402…-45781…}] initiating a split based on load at key /Table/53/1/-8768249731886885702 +test-0002> I181130 22:14:50.203299 6163815 storage/replica_command.go:342 [T1,n2,split,s2,r171/3:/Table/53/1/-87{94402…-45781…}] initiating a split of this range at key /Table/53/1/-8768249731886885702 [r588] +test-0001> I181130 22:14:57.522236 441 server/status/runtime.go:465 [T1,n1] runtime stats: 986 MiB RSS, 1332 goroutines, 438 MiB/140 MiB/777 MiB GO alloc/idle/total, 151 MiB/203 MiB CGO alloc/total, 137663.6 CGO/sec, 2168.3/222.8 %(u/s)time, 0.4 %gc (45x), 192 MiB/203 MiB (r/w)net +test-0002> I181130 22:14:57.650774 499 server/status/runtime.go:465 [T1,n2] runtime stats: 729 MiB RSS, 1127 goroutines, 416 MiB/91 MiB/584 MiB GO alloc/idle/total, 75 MiB/128 MiB CGO alloc/total, 111534.7 CGO/sec, 2013.0/232.3 %(u/s)time, 0.4 %gc (56x), 189 MiB/189 MiB (r/w)net +test-0002> I181130 22:15:05.892547 6507691 storage/split_queue.go:213 [T1,n2,split,s2,r129/3:/Table/53/1/-{722633…-673989…}] initiating a split based on load at key /Table/53/1/-698671514117501959 +test-0002> I181130 22:15:05.892592 6507691 storage/replica_command.go:342 [T1,n2,split,s2,r129/3:/Table/53/1/-{722633…-673989…}] initiating a split of this range at key /Table/53/1/-698671514117501959 [r589] +test-0001> I181130 22:15:07.525316 441 server/status/runtime.go:465 [T1,n1] runtime stats: 952 MiB RSS, 1422 goroutines, 397 MiB/165 MiB/777 MiB GO alloc/idle/total, 112 MiB/164 MiB CGO alloc/total, 133359.9 CGO/sec, 2137.8/225.1 %(u/s)time, 0.4 %gc (43x), 187 MiB/198 MiB (r/w)net +test-0002> I181130 22:15:07.653821 499 server/status/runtime.go:465 [T1,n2] runtime stats: 756 MiB RSS, 1127 goroutines, 338 MiB/113 MiB/584 MiB GO alloc/idle/total, 94 MiB/149 MiB CGO alloc/total, 108469.2 CGO/sec, 1964.7/227.0 %(u/s)time, 0.4 %gc (54x), 185 MiB/184 MiB (r/w)net diff --git a/pkg/cli/testdata/merge_logs_crdb-v2/results/3.non-standard b/pkg/cli/testdata/merge_logs_crdb-v2/results/3.non-standard index a1005a6d8dca..aeb88c5ac4d5 100644 --- a/pkg/cli/testdata/merge_logs_crdb-v2/results/3.non-standard +++ b/pkg/cli/testdata/merge_logs_crdb-v2/results/3.non-standard @@ -1,20 +1,20 @@ -I181130 22:14:34.828612 740 storage/store_rebalancer.go:277 [n1,s1,store-rebalancer] load-based lease transfers successfully brought s1 down to 37128.65 qps (mean=29834.62, upperThreshold=37293.27) -I181130 22:14:37.516378 441 server/status/runtime.go:465 [n1] runtime stats: 900 MiB RSS, 1509 goroutines, 421 MiB/144 MiB/777 MiB GO alloc/idle/total, 96 MiB/144 MiB CGO alloc/total, 154632.4 CGO/sec, 2206.9/216.0 %(u/s)time, 0.4 %gc (43x), 182 MiB/204 MiB (r/w)net -I181130 22:14:47.400515 437 gossip/gossip.go:555 [n1] gossip status (ok, 3 nodes) +I181130 22:14:34.828612 740 storage/store_rebalancer.go:277 [T1,n1,s1,store-rebalancer] load-based lease transfers successfully brought s1 down to 37128.65 qps (mean=29834.62, upperThreshold=37293.27) +I181130 22:14:37.516378 441 server/status/runtime.go:465 [T1,n1] runtime stats: 900 MiB RSS, 1509 goroutines, 421 MiB/144 MiB/777 MiB GO alloc/idle/total, 96 MiB/144 MiB CGO alloc/total, 154632.4 CGO/sec, 2206.9/216.0 %(u/s)time, 0.4 %gc (43x), 182 MiB/204 MiB (r/w)net +I181130 22:14:47.400515 437 gossip/gossip.go:555 [T1,n1] gossip status (ok, 3 nodes) gossip client (0/3 cur/max conns) gossip server (2/3 cur/max conns, infos 4077/2242 sent/received, bytes 1275332B/555352B sent/received) 2: ajwerner-test-0002:26257 (8m0s) 3: ajwerner-test-0003:26257 (8m0s) -I181130 22:14:47.519324 441 server/status/runtime.go:465 [n1] runtime stats: 957 MiB RSS, 1690 goroutines, 420 MiB/173 MiB/777 MiB GO alloc/idle/total, 124 MiB/174 MiB CGO alloc/total, 143837.6 CGO/sec, 2245.9/218.3 %(u/s)time, 0.5 %gc (47x), 199 MiB/210 MiB (r/w)net -I181130 22:14:49.706516 6152567 storage/split_queue.go:213 [n2,split,s2,r163/3:/Table/53/1/-36{84178…-35915…}] initiating a split based on load at key /Table/53/1/-3661595080111255049 -I181130 22:14:49.706563 6152567 storage/replica_command.go:342 [n2,split,s2,r163/3:/Table/53/1/-36{84178…-35915…}] initiating a split of this range at key /Table/53/1/-3661595080111255049 [r586] -I181130 22:14:49.732930 6153357 storage/split_queue.go:213 [n2,split,s2,r269/3:/Table/53/1/-81{56147…-10716…}] initiating a split based on load at key /Table/53/1/-8134885765915906309 -I181130 22:14:49.732976 6153357 storage/replica_command.go:342 [n2,split,s2,r269/3:/Table/53/1/-81{56147…-10716…}] initiating a split of this range at key /Table/53/1/-8134885765915906309 [r587] -I181130 22:14:50.203263 6163815 storage/split_queue.go:213 [n2,split,s2,r171/3:/Table/53/1/-87{94402…-45781…}] initiating a split based on load at key /Table/53/1/-8768249731886885702 -I181130 22:14:50.203299 6163815 storage/replica_command.go:342 [n2,split,s2,r171/3:/Table/53/1/-87{94402…-45781…}] initiating a split of this range at key /Table/53/1/-8768249731886885702 [r588] -I181130 22:14:57.522236 441 server/status/runtime.go:465 [n1] runtime stats: 986 MiB RSS, 1332 goroutines, 438 MiB/140 MiB/777 MiB GO alloc/idle/total, 151 MiB/203 MiB CGO alloc/total, 137663.6 CGO/sec, 2168.3/222.8 %(u/s)time, 0.4 %gc (45x), 192 MiB/203 MiB (r/w)net -I181130 22:14:57.650774 499 server/status/runtime.go:465 [n2] runtime stats: 729 MiB RSS, 1127 goroutines, 416 MiB/91 MiB/584 MiB GO alloc/idle/total, 75 MiB/128 MiB CGO alloc/total, 111534.7 CGO/sec, 2013.0/232.3 %(u/s)time, 0.4 %gc (56x), 189 MiB/189 MiB (r/w)net -I181130 22:15:05.892547 6507691 storage/split_queue.go:213 [n2,split,s2,r129/3:/Table/53/1/-{722633…-673989…}] initiating a split based on load at key /Table/53/1/-698671514117501959 -I181130 22:15:05.892592 6507691 storage/replica_command.go:342 [n2,split,s2,r129/3:/Table/53/1/-{722633…-673989…}] initiating a split of this range at key /Table/53/1/-698671514117501959 [r589] -I181130 22:15:07.525316 441 server/status/runtime.go:465 [n1] runtime stats: 952 MiB RSS, 1422 goroutines, 397 MiB/165 MiB/777 MiB GO alloc/idle/total, 112 MiB/164 MiB CGO alloc/total, 133359.9 CGO/sec, 2137.8/225.1 %(u/s)time, 0.4 %gc (43x), 187 MiB/198 MiB (r/w)net -I181130 22:15:07.653821 499 server/status/runtime.go:465 [n2] runtime stats: 756 MiB RSS, 1127 goroutines, 338 MiB/113 MiB/584 MiB GO alloc/idle/total, 94 MiB/149 MiB CGO alloc/total, 108469.2 CGO/sec, 1964.7/227.0 %(u/s)time, 0.4 %gc (54x), 185 MiB/184 MiB (r/w)net +I181130 22:14:47.519324 441 server/status/runtime.go:465 [T1,n1] runtime stats: 957 MiB RSS, 1690 goroutines, 420 MiB/173 MiB/777 MiB GO alloc/idle/total, 124 MiB/174 MiB CGO alloc/total, 143837.6 CGO/sec, 2245.9/218.3 %(u/s)time, 0.5 %gc (47x), 199 MiB/210 MiB (r/w)net +I181130 22:14:49.706516 6152567 storage/split_queue.go:213 [T1,n2,split,s2,r163/3:/Table/53/1/-36{84178…-35915…}] initiating a split based on load at key /Table/53/1/-3661595080111255049 +I181130 22:14:49.706563 6152567 storage/replica_command.go:342 [T1,n2,split,s2,r163/3:/Table/53/1/-36{84178…-35915…}] initiating a split of this range at key /Table/53/1/-3661595080111255049 [r586] +I181130 22:14:49.732930 6153357 storage/split_queue.go:213 [T1,n2,split,s2,r269/3:/Table/53/1/-81{56147…-10716…}] initiating a split based on load at key /Table/53/1/-8134885765915906309 +I181130 22:14:49.732976 6153357 storage/replica_command.go:342 [T1,n2,split,s2,r269/3:/Table/53/1/-81{56147…-10716…}] initiating a split of this range at key /Table/53/1/-8134885765915906309 [r587] +I181130 22:14:50.203263 6163815 storage/split_queue.go:213 [T1,n2,split,s2,r171/3:/Table/53/1/-87{94402…-45781…}] initiating a split based on load at key /Table/53/1/-8768249731886885702 +I181130 22:14:50.203299 6163815 storage/replica_command.go:342 [T1,n2,split,s2,r171/3:/Table/53/1/-87{94402…-45781…}] initiating a split of this range at key /Table/53/1/-8768249731886885702 [r588] +I181130 22:14:57.522236 441 server/status/runtime.go:465 [T1,n1] runtime stats: 986 MiB RSS, 1332 goroutines, 438 MiB/140 MiB/777 MiB GO alloc/idle/total, 151 MiB/203 MiB CGO alloc/total, 137663.6 CGO/sec, 2168.3/222.8 %(u/s)time, 0.4 %gc (45x), 192 MiB/203 MiB (r/w)net +I181130 22:14:57.650774 499 server/status/runtime.go:465 [T1,n2] runtime stats: 729 MiB RSS, 1127 goroutines, 416 MiB/91 MiB/584 MiB GO alloc/idle/total, 75 MiB/128 MiB CGO alloc/total, 111534.7 CGO/sec, 2013.0/232.3 %(u/s)time, 0.4 %gc (56x), 189 MiB/189 MiB (r/w)net +I181130 22:15:05.892547 6507691 storage/split_queue.go:213 [T1,n2,split,s2,r129/3:/Table/53/1/-{722633…-673989…}] initiating a split based on load at key /Table/53/1/-698671514117501959 +I181130 22:15:05.892592 6507691 storage/replica_command.go:342 [T1,n2,split,s2,r129/3:/Table/53/1/-{722633…-673989…}] initiating a split of this range at key /Table/53/1/-698671514117501959 [r589] +I181130 22:15:07.525316 441 server/status/runtime.go:465 [T1,n1] runtime stats: 952 MiB RSS, 1422 goroutines, 397 MiB/165 MiB/777 MiB GO alloc/idle/total, 112 MiB/164 MiB CGO alloc/total, 133359.9 CGO/sec, 2137.8/225.1 %(u/s)time, 0.4 %gc (43x), 187 MiB/198 MiB (r/w)net +I181130 22:15:07.653821 499 server/status/runtime.go:465 [T1,n2] runtime stats: 756 MiB RSS, 1127 goroutines, 338 MiB/113 MiB/584 MiB GO alloc/idle/total, 94 MiB/149 MiB CGO alloc/total, 108469.2 CGO/sec, 1964.7/227.0 %(u/s)time, 0.4 %gc (54x), 185 MiB/184 MiB (r/w)net diff --git a/pkg/cli/testdata/merge_logs_crdb-v2/results/4.filter b/pkg/cli/testdata/merge_logs_crdb-v2/results/4.filter index acd2c58d4b4f..e908b7b6232c 100644 --- a/pkg/cli/testdata/merge_logs_crdb-v2/results/4.filter +++ b/pkg/cli/testdata/merge_logs_crdb-v2/results/4.filter @@ -1,2 +1,2 @@ -> E190412 10:06:00.645112 195432 storage/queue.go:866 [n1,replicate,s1,r161/2:/Table/84/{1/5/7-2}] no removable replicas from range that needs a removal: [2*:27, 3:0] -> E190412 10:06:00.818605 195938 storage/queue.go:866 [n1,replicate,s1,r159/2:/Table/84/1/{4-5/6}] no removable replicas from range that needs a removal: [2*:27, 3:0] +> E190412 10:06:00.645112 195432 storage/queue.go:866 [T1,n1,replicate,s1,r161/2:/Table/84/{1/5/7-2}] no removable replicas from range that needs a removal: [2*:27, 3:0] +> E190412 10:06:00.818605 195938 storage/queue.go:866 [T1,n1,replicate,s1,r159/2:/Table/84/1/{4-5/6}] no removable replicas from range that needs a removal: [2*:27, 3:0] diff --git a/pkg/cli/testdata/merge_logs_crdb-v2/results/5.redact-off-redactable-off b/pkg/cli/testdata/merge_logs_crdb-v2/results/5.redact-off-redactable-off index d24297ff394a..ec1fb98ce872 100644 --- a/pkg/cli/testdata/merge_logs_crdb-v2/results/5.redact-off-redactable-off +++ b/pkg/cli/testdata/merge_logs_crdb-v2/results/5.redact-off-redactable-off @@ -1,2 +1,2 @@ -> I190412 10:06:00.490104 183717 server/server.go:1423 [-] safe unsafe -> I190412 10:06:00.490104 183717 server/server.go:1424 [-] unknownsafe +> I190412 10:06:00.490104 183717 server/server.go:1423 [T1] safe unsafe +> I190412 10:06:00.490104 183717 server/server.go:1424 [T1] unknownsafe diff --git a/pkg/cli/testdata/merge_logs_crdb-v2/results/5.redact-off-redactable-on b/pkg/cli/testdata/merge_logs_crdb-v2/results/5.redact-off-redactable-on index e9b765d63575..1b72e52d1f78 100644 --- a/pkg/cli/testdata/merge_logs_crdb-v2/results/5.redact-off-redactable-on +++ b/pkg/cli/testdata/merge_logs_crdb-v2/results/5.redact-off-redactable-on @@ -1,2 +1,2 @@ -> I190412 10:06:00.490104 183717 server/server.go:1423 ⋮ [-] safe ‹unsafe› -> I190412 10:06:00.490104 183717 server/server.go:1424 ⋮ [-] ‹unknownsafe› +> I190412 10:06:00.490104 183717 server/server.go:1423 ⋮ [T1] safe ‹unsafe› +> I190412 10:06:00.490104 183717 server/server.go:1424 ⋮ [T1] ‹unknownsafe› diff --git a/pkg/cli/testdata/merge_logs_crdb-v2/results/5.redact-on-redactable-off b/pkg/cli/testdata/merge_logs_crdb-v2/results/5.redact-on-redactable-off index 5dd1937c09a8..acc01ec7086a 100644 --- a/pkg/cli/testdata/merge_logs_crdb-v2/results/5.redact-on-redactable-off +++ b/pkg/cli/testdata/merge_logs_crdb-v2/results/5.redact-on-redactable-off @@ -1,2 +1,2 @@ -> I190412 10:06:00.490104 183717 server/server.go:1423 [-] safe × -> I190412 10:06:00.490104 183717 server/server.go:1424 [-] × +> I190412 10:06:00.490104 183717 server/server.go:1423 [T1] safe × +> I190412 10:06:00.490104 183717 server/server.go:1424 [T1] × diff --git a/pkg/cli/testdata/merge_logs_crdb-v2/results/5.redact-on-redactable-on b/pkg/cli/testdata/merge_logs_crdb-v2/results/5.redact-on-redactable-on index b0a69a9466b7..498a0b05e6d9 100644 --- a/pkg/cli/testdata/merge_logs_crdb-v2/results/5.redact-on-redactable-on +++ b/pkg/cli/testdata/merge_logs_crdb-v2/results/5.redact-on-redactable-on @@ -1,2 +1,2 @@ -> I190412 10:06:00.490104 183717 server/server.go:1423 ⋮ [-] safe ‹×› -> I190412 10:06:00.490104 183717 server/server.go:1424 ⋮ [-] ‹×› +> I190412 10:06:00.490104 183717 server/server.go:1423 ⋮ [T1] safe ‹×› +> I190412 10:06:00.490104 183717 server/server.go:1424 ⋮ [T1] ‹×› diff --git a/pkg/server/debug/BUILD.bazel b/pkg/server/debug/BUILD.bazel index 023bbfb7100b..330179ab36ef 100644 --- a/pkg/server/debug/BUILD.bazel +++ b/pkg/server/debug/BUILD.bazel @@ -52,12 +52,14 @@ go_test( args = ["-test.timeout=55s"], embed = [":debug"], deps = [ + "//pkg/roachpb", "//pkg/testutils", "//pkg/util/leaktest", "//pkg/util/log", "//pkg/util/log/logpb", "//pkg/util/syncutil", "@com_github_cockroachdb_errors//:errors", + "@com_github_stretchr_testify//require", ], ) diff --git a/pkg/server/debug/logspy.go b/pkg/server/debug/logspy.go index c8b2bdb9ca30..3c112486f987 100644 --- a/pkg/server/debug/logspy.go +++ b/pkg/server/debug/logspy.go @@ -22,6 +22,7 @@ import ( "sync/atomic" "time" + "github.com/cockroachdb/cockroach/pkg/roachpb" "github.com/cockroachdb/cockroach/pkg/util/log" "github.com/cockroachdb/cockroach/pkg/util/log/channel" "github.com/cockroachdb/cockroach/pkg/util/log/logpb" @@ -96,6 +97,10 @@ type logSpyOptions struct { Grep regexpAsString Flatten intAsString vmoduleOptions `json:",inline"` + // tenantIDFilter filters entries based on the provided tenant ID. + // If empty, no filtering is applied (only relevant for the system + // tenant). + tenantIDFilter string } func logSpyOptionsFromValues(values url.Values) (logSpyOptions, error) { @@ -121,6 +126,11 @@ func logSpyOptionsFromValues(values url.Values) (logSpyOptions, error) { } type logSpy struct { + // tenantID is the tenantID assigned to the server that's servicing this + // logSpy. If the value is any tenant other than the System tenant, we + // filter logs to only include those specific to this tenantID. For the + // system tenant however, we perform no such filtering. + tenantID roachpb.TenantID vsrv *vmoduleServer setIntercept func(ctx context.Context, f log.Interceptor) func() } @@ -131,6 +141,9 @@ func (spy *logSpy) handleDebugLogSpy(w http.ResponseWriter, r *http.Request) { http.Error(w, "while parsing options: "+err.Error(), http.StatusInternalServerError) return } + if spy.tenantID != roachpb.SystemTenantID { + opts.tenantIDFilter = spy.tenantID.String() + } w.Header().Add("Content-type", "text/plain; charset=UTF-8") ctx := r.Context() @@ -148,7 +161,7 @@ func (spy *logSpy) run(ctx context.Context, w io.Writer, opts logSpyOptions) (er // is never closed. This is because we don't know when that is // safe. This is sketchy in general but OK here since we don't have // to guarantee that the channel is fully consumed. - interceptor := newLogSpyInterceptor(opts) + interceptor := newLogSpyInterceptor(ctx, opts) defer func() { if dropped := atomic.LoadInt32(&interceptor.countDropped); dropped > 0 { @@ -156,7 +169,11 @@ func (spy *logSpy) run(ctx context.Context, w io.Writer, opts logSpyOptions) (er ctx, severity.WARNING, channel.DEV, 0 /* depth */, true, /* redactable */ "%d messages were dropped", redact.Safe(dropped)) - err = errors.CombineErrors(err, interceptor.outputEntry(w, entry)) + entryBytes, _ := json.Marshal(entry) + err = errors.CombineErrors(err, interceptor.outputEntry(w, logSpyInterceptorPayload{ + entryBytes: entryBytes, + entry: entry, + })) } }() @@ -211,9 +228,12 @@ func (spy *logSpy) run(ctx context.Context, w io.Writer, opts logSpyOptions) (er } return err - case jsonEntry := <-interceptor.jsonEntries: - if err := interceptor.outputJSONEntry(w, jsonEntry); err != nil { - return errors.Wrapf(err, "while writing entry %s", jsonEntry) + case entryPayload := <-interceptor.jsonEntries: + if entryPayload.err != nil { + return err + } + if err := interceptor.outputEntry(w, entryPayload); err != nil { + return errors.Wrapf(err, "while writing entry %s", entryPayload.entryBytes) } numReportedEntries++ if numReportedEntries >= int(opts.Count) { @@ -231,15 +251,32 @@ func (spy *logSpy) run(ctx context.Context, w io.Writer, opts logSpyOptions) (er } type logSpyInterceptor struct { + ctx context.Context opts logSpyOptions countDropped int32 - jsonEntries chan []byte + jsonEntries chan logSpyInterceptorPayload +} + +// logSpyInterceptorPayload exists for convenience. When we first +// intercept, we need to perform some basic filtering that requires +// us to unmarshall the entryBytes. Instead of performing this +// operation multiple times, we store the entry in the payload +// for reuse. +type logSpyInterceptorPayload struct { + // The raw log entry bytes. + entryBytes []byte + // The unmarshalled result from entryBytes. + entry logpb.Entry + // If an error occurred during the intercept, we place it here + // to be processed by the logSpy consumer. + err error } -func newLogSpyInterceptor(opts logSpyOptions) *logSpyInterceptor { +func newLogSpyInterceptor(ctx context.Context, opts logSpyOptions) *logSpyInterceptor { return &logSpyInterceptor{ + ctx: ctx, opts: opts, - jsonEntries: make(chan []byte, logSpyChanCap), + jsonEntries: make(chan logSpyInterceptorPayload, logSpyChanCap), } } @@ -251,6 +288,22 @@ func (i *logSpyInterceptor) Intercept(jsonEntry []byte) { return } } + var entry logpb.Entry + if err := json.Unmarshal(jsonEntry, &entry); err != nil { + // If we can't unmarshal the entry, send an error along to be handled by the consumer and return. + select { + case i.jsonEntries <- logSpyInterceptorPayload{ + err: errors.Wrapf(err, "logspy failed to unmarshal entry: %s", jsonEntry), + }: + default: + // Consumer fell behind, just drop the message. + atomic.AddInt32(&i.countDropped, 1) + } + return + } + if i.opts.tenantIDFilter != "" && i.opts.tenantIDFilter != entry.TenantID { + return + } // The log.Interceptor interface requires us to copy the buffer // before we can send it to a different goroutine. @@ -258,30 +311,21 @@ func (i *logSpyInterceptor) Intercept(jsonEntry []byte) { copy(jsonCopy, jsonEntry) select { - case i.jsonEntries <- jsonCopy: + case i.jsonEntries <- logSpyInterceptorPayload{ + entryBytes: jsonCopy, + entry: entry, + }: default: // Consumer fell behind, just drop the message. atomic.AddInt32(&i.countDropped, 1) } } -func (i *logSpyInterceptor) outputEntry(w io.Writer, entry logpb.Entry) error { - if i.opts.Flatten > 0 { - return log.FormatLegacyEntry(entry, w) - } - j, _ := json.Marshal(entry) - return i.outputJSONEntry(w, j) -} - -func (i *logSpyInterceptor) outputJSONEntry(w io.Writer, jsonEntry []byte) error { +func (i *logSpyInterceptor) outputEntry(w io.Writer, entry logSpyInterceptorPayload) error { if i.opts.Flatten == 0 { - _, err1 := w.Write(jsonEntry) + _, err1 := w.Write(entry.entryBytes) _, err2 := w.Write([]byte("\n")) return errors.CombineErrors(err1, err2) } - var legacyEntry logpb.Entry - if err := json.Unmarshal(jsonEntry, &legacyEntry); err != nil { - return errors.NewAssertionErrorWithWrappedErrf(err, "interceptor API does not seem to provide valid Entry payloads") - } - return i.outputEntry(w, legacyEntry) + return log.FormatLegacyEntry(entry.entry, w) } diff --git a/pkg/server/debug/logspy_test.go b/pkg/server/debug/logspy_test.go index db0b40e112d3..36864291e861 100644 --- a/pkg/server/debug/logspy_test.go +++ b/pkg/server/debug/logspy_test.go @@ -23,12 +23,14 @@ import ( "testing" "time" + "github.com/cockroachdb/cockroach/pkg/roachpb" "github.com/cockroachdb/cockroach/pkg/testutils" "github.com/cockroachdb/cockroach/pkg/util/leaktest" "github.com/cockroachdb/cockroach/pkg/util/log" "github.com/cockroachdb/cockroach/pkg/util/log/logpb" "github.com/cockroachdb/cockroach/pkg/util/syncutil" "github.com/cockroachdb/errors" + "github.com/stretchr/testify/require" ) func TestDebugLogSpyOptions(t *testing.T) { @@ -143,6 +145,7 @@ func TestDebugLogSpyRun(t *testing.T) { send <- f return func() {} }, + tenantID: roachpb.SystemTenantID, } ctx, cancel := context.WithCancel(context.Background()) defer cancel() @@ -166,19 +169,22 @@ func TestDebugLogSpyRun(t *testing.T) { t.Logf("got interceptor, sending some events") f.Intercept(toJSON(t, logpb.Entry{ - File: "first.go", - Line: 1, - Message: "#1", + File: "first.go", + Line: 1, + Message: "#1", + TenantID: "1", })) f.Intercept(toJSON(t, logpb.Entry{ - File: "nonmatching.go", - Line: 12345, - Message: "ignored because neither message nor file match", + File: "nonmatching.go", + Line: 12345, + Message: "ignored because neither message nor file match", + TenantID: "1", })) f.Intercept(toJSON(t, logpb.Entry{ - File: "second.go", - Line: 2, - Message: "#2", + File: "second.go", + Line: 2, + Message: "#2", + TenantID: "2", })) if undoF := <-send; undoF != nil { t.Fatal("interceptor closed with non-nil function") @@ -196,8 +202,96 @@ func TestDebugLogSpyRun(t *testing.T) { t.Logf("check results") body := buf.String() - const expected = `{"file":"first.go","line":1,"message":"#1"} -{"file":"second.go","line":2,"message":"#2"} + const expected = `{"file":"first.go","line":1,"message":"#1","tenant_id":"1"} +{"file":"second.go","line":2,"message":"#2","tenant_id":"2"} +` + if expected != body { + t.Fatalf("expected:\n%q\ngot:\n%q", expected, body) + } +} + +func TestDebugLogSpyTenantFilter(t *testing.T) { + defer leaktest.AfterTest(t)() + defer log.Scope(t).Close(t) + tID, err := roachpb.MakeTenantID(uint64(2)) + require.NoError(t, err) + otherTenantID, err := roachpb.MakeTenantID(uint64(3)) + require.NoError(t, err) + // Logs for now use the integer representation for + // all tenant IDs, so use `1` instead of `system`. + sysTenantIDStr := "1" + + send := make(chan log.Interceptor, 1) + spy := logSpy{ + setIntercept: func(ctx context.Context, f log.Interceptor) func() { + send <- f + return func() {} + }, + tenantID: tID, + } + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + + var buf bytes.Buffer + go func() { + defer func() { + close(send) + }() + if err := spy.run(ctx, &buf, logSpyOptions{ + vmoduleOptions: vmoduleOptions{Duration: durationAsString(5 * time.Second)}, + Count: 2, + tenantIDFilter: tID.String(), + }); err != nil { + panic(err) + } + }() + + t.Logf("waiting for interceptor") + f := <-send + t.Logf("got interceptor, sending some events") + + f.Intercept(toJSON(t, logpb.Entry{ + File: "first.go", + Line: 1, + Message: "#1", + TenantID: tID.String(), + })) + f.Intercept(toJSON(t, logpb.Entry{ + File: "second.go", + Line: 12345, + Message: "ignored because tenant ID does not match filter", + TenantID: otherTenantID.String(), + })) + f.Intercept(toJSON(t, logpb.Entry{ + File: "third.go", + Line: 12345, + Message: "also ignored because tenant ID does not match filter", + TenantID: sysTenantIDStr, + })) + f.Intercept(toJSON(t, logpb.Entry{ + File: "fourth.go", + Line: 2, + Message: "#2", + TenantID: tID.String(), + })) + if undoF := <-send; undoF != nil { + t.Fatal("interceptor closed with non-nil function") + } + + t.Logf("fill in the channel") + + for i := 0; i < 10000; i++ { + // f could be invoked arbitrarily after the operation finishes (though + // in reality the duration would be limited to the blink of an eye). It + // must not fill up a channel and block, or panic. + f.Intercept(toJSON(t, logpb.Entry{})) + } + + t.Logf("check results") + + body := buf.String() + const expected = `{"file":"first.go","line":1,"message":"#1","tenant_id":"2"} +{"file":"fourth.go","line":2,"message":"#2","tenant_id":"2"} ` if expected != body { t.Fatalf("expected:\n%q\ngot:\n%q", expected, body) diff --git a/pkg/server/debug/server.go b/pkg/server/debug/server.go index 6a64ccc0bb94..1c2be93207c6 100644 --- a/pkg/server/debug/server.go +++ b/pkg/server/debug/server.go @@ -17,6 +17,7 @@ import ( "io" "net/http" "net/http/pprof" + "strconv" "github.com/cockroachdb/cockroach/pkg/base" "github.com/cockroachdb/cockroach/pkg/kv/kvserver" @@ -129,11 +130,22 @@ func NewServer( mux.HandleFunc("/debug/vmodule", vsrv.vmoduleHandleDebug) // Set up the log spy, a tool that allows inspecting filtered logs at high - // verbosity. + // verbosity. We require the tenant ID from the ambientCtx to set the logSpy + // tenant filter. spy := logSpy{ vsrv: vsrv, setIntercept: log.InterceptWith, } + serverTenantID := ambientContext.ServerIDs.ServerIdentityString(log.IdentifyTenantID) + if serverTenantID == "" { + panic("programmer error: cannot instantiate a debug.Server with no tenantID in the ambientCtx") + } + parsed, err := strconv.ParseUint(serverTenantID, 10, 64) + if err != nil { + panic("programmer error: failed parsing ambientCtx tenantID during debug.Server initialization") + } + spy.tenantID = roachpb.MustMakeTenantID(parsed) + mux.HandleFunc("/debug/logspy", spy.handleDebugLogSpy) ps := pprofui.NewServer(pprofui.NewMemStorage(pprofui.ProfileConcurrency, pprofui.ProfileExpiry), profiler)