[BUG] Problems with online migration

Knud3 commented 1 year ago

TL;DR: activated online migration > data was lose > old schema was still in place. Also CPU usage was high (0.06/8 > 2.06/8) and go-carbon process wont start anymore.

I tried online migration with latest build last friday.

[whisper]
online-migration = true
online-migration-rate = 5
online-migration-global-scope = "xff,aggregationMethod,schema"

I tested it with metrics which had 5m:1d,1h:1y schema. Changed to 1m:14d,1h:1y.

[bar]
pattern = ^foo\.bar\.
retentions = 1m:14d,1h:1y

find ./whisper/foo/bar -type f | wc -l
206007

All started well, but migration rate dropped almost instantly, but CPU usage stayed high (additional 100% for two cores). Also disk write rate was high for some hours.

cpu

migration

Now after weekend when it had about 70 hours time to process, it seems that it have lose all data for those changed metrics (also 1h:1y). And not just that, but metrics where still with previous 5m:1d,1h:1y schema.

I tried to restart go-carbon process, but it crashed almost instantly with

textPayload: "panic: runtime error: index out of range [0] with length 0

goroutine 114 [running]:
github.com/go-graphite/go-carbon/carbonserver.(*CarbonserverListener).fetchData(0xc0000cc000, {0xc09f245f40, 0x45}, {0xc09f245f40, 0x45}, {0xc091adfd60?, 0x1, 0x4382b3?}, {0xc0b0985779, 0x1, ...}, ...)
    /usr/local/src/go-carbon/carbonserver/render.go:608 +0x978
github.com/go-graphite/go-carbon/carbonserver.(*CarbonserverListener).prepareDataStream(0xc0000cc000, {0xf6f4b8, 0xc0b09b6cc0}, 0x3, 0xc0b09e1140?, 0xc0b0a26db0?, 0xc0b09b71a0)
    /usr/local/src/go-carbon/carbonserver/render.go:442 +0xd17
github.com/go-graphite/go-carbon/carbonserver.(*CarbonserverListener).prepareDataProto.func1()
    /usr/local/src/go-carbon/carbonserver/render.go:489 +0xb3
created by github.com/go-graphite/go-carbon/carbonserver.(*CarbonserverListener).prepareDataProto
    /usr/local/src/go-carbon/carbonserver/render.go:487 +0x4d5"
timestamp: "2023-01-23T08:57:38.255363552Z"

textPayload: "panic: runtime error: index out of range [0] with length 0

goroutine 264 [running]:
github.com/go-graphite/go-carbon/carbonserver.(*CarbonserverListener).fetchData(0xc0004e4380, {0xc06adb2820, 0x45}, {0xc06adb2820, 0x45}, {0xc062c7dc60?, 0x1, 0x4382b3?}, {0xc0630a7693, 0x1, ...}, ...)
    /usr/local/src/go-carbon/carbonserver/render.go:608 +0x978
github.com/go-graphite/go-carbon/carbonserver.(*CarbonserverListener).prepareDataStream(0xc0004e4380, {0xf6f4b8, 0xc09fcb56e0}, 0x3, 0xc0610f8cc0?, 0xc061ccb080?, 0xc09fcb5bc0)
    /usr/local/src/go-carbon/carbonserver/render.go:442 +0xd17
github.com/go-graphite/go-carbon/carbonserver.(*CarbonserverListener).prepareDataProto.func1()
    /usr/local/src/go-carbon/carbonserver/render.go:489 +0xb3
created by github.com/go-graphite/go-carbon/carbonserver.(*CarbonserverListener).prepareDataProto
    /usr/local/src/go-carbon/carbonserver/render.go:487 +0x4d5"
timestamp: "2023-01-23T08:58:00.106458336Z"

Had to downgrade to v0.16.2 to get it working again.

What do you recommend to get migration working?

Knud3 commented 1 year ago

Also questions:

If go-carbon process is killed in middle of migration, does it continue migration where it left after process is up again?
What changes in configs needs go-carbon restart to apply?

bom-d-van commented 1 year ago

Hi, is it possible for you turn on debug logging level and share some of the whisper files that were causing panics?

If go-carbon process is killed in middle of migration, does it continue migration where it left after process is up again?

Yes, online migrations are triggered when there are updates on the metric/whisper files. If there are no write to the whisper files, then migrations are not triggered.

What changes in configs needs go-carbon restart to apply?

To be on the safe side, when I was operating on a graphite cluster/instances, I always triggered a restart when updating go-carbon configs.

bom-d-van commented 1 year ago

All started well, but migration rate dropped almost instantly, but CPU usage stayed high (additional 100% for two cores). Also disk write rate was high for some hours.

can you use perf top or dump a cpu profiling with the golang debug trace tooling and share it, this would give us insight into what the cpu is doing?

also you need to make sure that there is no increased read rate from your clients or users towards the cluster.

bom-d-van commented 1 year ago

Now after weekend when it had about 70 hours time to process, it seems that it have lose all data for those changed metrics (also 1h:1y). And not just that, but metrics where still with previous 5m:1d,1h:1y schema.

for this part, you can refer the online schema migration doc about the current behavior.

however, data in 1h:1y archive should be migrated in your schema changes, can you also share a whisper file with us as a reference.

also maybe you want to check if there are any useful errors or panic logs in go-carbon.log or systemd.

Knud3 commented 1 year ago

Thank you for taking time to explain.

Hi, is it possible for you turn on debug logging level

Yes I assume. I get back with this.

and share some of the whisper files that were causing panics?

Well, I assume panics was caused by migrated files, but how can I be sure? And I'm not sure that can I share those files anyway.

Yes, online migrations are triggered when there are updates on the metric/whisper files. If there are no write to the whisper files, then migrations are not triggered.

Thank you for clarifying this. Does online-migration-rate mean metric files per second? So, there are some kind of queue for migration files? Does that queue form again in case of go-carbon process restart (assuming there are writes to whisper files)?

To be on the safe side, when I was operating on a graphite cluster/instances, I always triggered a restart when updating go-carbon configs.

I have done the same.

can you use perf top

It might be problematic in Alpine container.

or dump a cpu profiling with the golang debug trace tooling and share it, this would give us insight into what the cpu is doing?

Can you elaborate how to do this?

also you need to make sure that there is no increased read rate from your clients or users towards the cluster.

That was not the case.

for this part, you can refer the online schema migration doc about the current behavior.

however, data in 1h:1y archive should be migrated in your schema changes, can you also share a whisper file with us as a reference.

I have read that documentation carefully and was expecting to lose 5m:1d, but not 1h:1y. BTW, what does it mean that temporary file is required when schema changes? Where does it saves that file?

also maybe you want to check if there are any useful errors or panic logs in go-carbon.log or systemd.

System is read only. Only writeable dir is /var/lib/graphite. There were no any meaninful errors in stderr.

This is when migration happened /var/lib/graphite/carbonserver/LOG

=============== Jan 20, 2023 (UTC) ===============
11:00:24.347856 log@legend F·NumFile S·FileSize N·Entry C·BadEntry B·BadBlock Ke·KeyError D·DroppedEntry L·Level Q·SeqNum T·TimeElapsed
11:00:24.360382 version@stat F·[3 1] S·2MiB[1MiB 595KiB] Sc·[0.75 0.01]
11:00:24.360412 db@open opening
11:00:24.360956 journal@recovery F·1
11:00:24.492985 journal@recovery recovering @242
11:00:24.568394 memdb@flush created L0@244 N·10423 S·129KiB "car..ime,v3815026":"stg..ate,v3809178"
11:00:24.575095 version@stat F·[4 1] S·2MiB[1MiB 595KiB] Sc·[1.00 0.01]
11:00:24.586723 db@janitor F·7 G·0
11:00:24.586762 db@open done T·226.34112ms
11:00:24.601662 table@compaction L0·4 -> L1·1 S·2MiB Q·3816114
11:00:24.709728 table@build created L1@247 N·34720 S·597KiB "car..ize,v3674699":"stg..p99,v3291486"
11:00:24.709787 version@stat F·[0 1] S·597KiB[0B 597KiB] Sc·[0.00 0.01]
11:00:24.712023 table@compaction committed F-4 S-1MiB Ke·0 D·132458 T·110.290218ms
11:00:24.716080 table@remove removed @244
11:00:24.716248 table@remove removed @243
11:00:24.716418 table@remove removed @241
11:00:24.716597 table@remove removed @239
11:00:24.716815 table@remove removed @237
11:13:05.809083 memdb@flush N·41644 S·3MiB
11:13:05.836329 memdb@flush created L0@249 N·41644 S·502KiB "car..ize,v3855582":"stg..ate,v3817359"
11:13:05.836384 version@stat F·[1 1] S·1MiB[502KiB 597KiB] Sc·[0.25 0.01]
11:13:05.838846 memdb@flush committed F·1 T·29.669877ms
11:13:05.839560 journal@remove removed @245
11:13:27.483783 memdb@flush N·42866 S·3MiB
11:13:27.532079 memdb@flush created L0@251 N·42866 S·616KiB "car..ime,v3859797":"stg..ate,v3867702"
11:13:27.532134 version@stat F·[2 1] S·1MiB[1MiB 597KiB] Sc·[0.50 0.01]
11:13:27.557162 memdb@flush committed F·1 T·73.342822ms
11:13:27.557932 journal@remove removed @248
11:13:39.692653 memdb@flush N·39751 S·3MiB
11:13:39.731692 memdb@flush created L0@253 N·39751 S·573KiB "stg..ate,v3920364":"stg..ate,v3907902"
11:13:39.731787 version@stat F·[3 1] S·2MiB[1MiB 597KiB] Sc·[0.75 0.01]
11:13:39.741559 memdb@flush committed F·1 T·48.865732ms
11:13:39.742523 journal@remove removed @250
11:14:01.801212 memdb@flush N·43597 S·3MiB
11:14:01.851357 memdb@flush created L0@255 N·43597 S·632KiB "hes..unt,v3980669":"stg..ate,v3957158"
11:14:01.851419 version@stat F·[4 1] S·2MiB[2MiB 597KiB] Sc·[1.00 0.01]
11:14:01.857544 memdb@flush committed F·1 T·55.949536ms
11:14:01.859404 journal@remove removed @252
11:14:01.859501 table@compaction L0·4 -> L1·1 S·2MiB Q·3986414
11:14:01.964461 table@build created L1@256 N·34748 S·596KiB "car..ize,v3855582":"stg..p99,v3291486"
11:14:01.964558 version@stat F·[0 1] S·596KiB[0B 596KiB] Sc·[0.00 0.01]
11:14:01.967925 table@compaction committed F-4 S-2MiB Ke·0 D·167830 T·108.374654ms
11:14:01.968206 table@remove removed @255
11:14:01.968380 table@remove removed @253
11:14:01.968574 table@remove removed @251
11:14:01.968717 table@remove removed @249
11:14:01.968885 table@remove removed @247
11:14:06.866401 memdb@flush N·40655 S·3MiB
11:14:06.912361 memdb@flush created L0@258 N·40655 S·597KiB "car..ime,v3987265":"stg..ate,v3984256"
11:14:06.912440 version@stat F·[1 1] S·1MiB[597KiB 596KiB] Sc·[0.25 0.01]
11:14:06.914606 memdb@flush committed F·1 T·48.155941ms
11:14:06.915580 journal@remove removed @254
11:14:18.321963 memdb@flush N·42852 S·3MiB
11:14:18.364838 memdb@flush created L0@260 N·42852 S·638KiB "car..ize,v4052285":"stg..p99,v4032983"
11:14:18.364876 version@stat F·[2 1] S·1MiB[1MiB 596KiB] Sc·[0.50 0.01]
11:14:18.367142 memdb@flush committed F·1 T·45.152122ms
11:14:18.368109 journal@remove removed @257
11:14:26.131254 memdb@flush N·43386 S·3MiB
11:14:26.260128 memdb@flush created L0@262 N·43386 S·643KiB "stg..ean,v4092330":"stg..p99,v4075668"
11:14:26.260194 version@stat F·[3 1] S·2MiB[1MiB 596KiB] Sc·[0.75 0.01]
11:14:26.263086 memdb@flush committed F·1 T·131.801082ms
11:14:26.263816 journal@remove removed @259
11:14:37.191352 memdb@flush N·43776 S·3MiB
11:14:37.223564 memdb@flush created L0@264 N·43776 S·655KiB "stg..ean,v4149295":"stg..p99,v4142103"
11:14:37.223621 version@stat F·[4 1] S·3MiB[2MiB 596KiB] Sc·[1.00 0.01]
11:14:37.225461 memdb@flush committed F·1 T·34.075256ms
11:14:37.226316 journal@remove removed @261
11:14:37.226368 table@compaction L0·4 -> L1·1 S·3MiB Q·4155281
11:14:37.305839 table@build created L1@265 N·34748 S·602KiB "car..ize,v3855582":"stg..p99,v4142103"
11:14:37.305900 version@stat F·[0 1] S·602KiB[0B 602KiB] Sc·[0.00 0.01]
11:14:37.307437 table@compaction committed F-4 S-2MiB Ke·0 D·170669 T·81.04865ms
11:14:37.307603 table@remove removed @264
11:14:37.307734 table@remove removed @262
11:14:37.307855 table@remove removed @260
11:14:37.307978 table@remove removed @258
11:14:37.308106 table@remove removed @256
11:14:54.899144 memdb@flush N·42377 S·3MiB
11:14:54.946155 memdb@flush created L0@267 N·42377 S·644KiB "stg..ean,v4176205":"stg..p99,v4169968"
11:14:54.946282 version@stat F·[1 1] S·1MiB[644KiB 602KiB] Sc·[0.25 0.01]
11:14:54.948573 memdb@flush committed F·1 T·49.352393ms
11:14:54.950155 journal@remove removed @263
11:15:10.604100 memdb@flush N·43185 S·3MiB
11:15:10.646539 memdb@flush created L0@269 N·43185 S·659KiB "car..ime,v4231198":"stg..p99,v4208340"
11:15:10.646587 version@stat F·[2 1] S·1MiB[1MiB 602KiB] Sc·[0.50 0.01]
11:15:10.649671 memdb@flush committed F·1 T·45.52557ms
11:15:10.650797 journal@remove removed @266
11:17:52.348667 memdb@flush N·43079 S·3MiB
11:17:52.406221 memdb@flush created L0@271 N·43079 S·660KiB "car..ize,v4265437":"stg..p99,v4241647"
11:17:52.406295 version@stat F·[3 1] S·2MiB[1MiB 602KiB] Sc·[0.75 0.01]
11:17:52.412455 memdb@flush committed F·1 T·63.729104ms
11:17:52.413625 journal@remove removed @268
11:18:12.680122 memdb@flush N·42757 S·3MiB
11:18:12.707781 memdb@flush created L0@273 N·42757 S·648KiB "car..ime,v4319504":"stg..ate,v4305542"
11:18:12.707836 version@stat F·[4 1] S·3MiB[2MiB 602KiB] Sc·[1.00 0.01]
11:18:12.709706 memdb@flush committed F·1 T·29.561426ms
11:18:12.710512 journal@remove removed @270
11:18:12.710680 table@compaction L0·4 -> L1·1 S·3MiB Q·4331039
11:18:12.795208 table@build created L1@274 N·47011 S·814KiB "car..ize,v4265437":"stg..p99,v4241647"
11:18:12.795256 version@stat F·[0 1] S·814KiB[0B 814KiB] Sc·[0.00 0.01]
11:18:12.797591 table@compaction committed F-4 S-2MiB Ke·0 D·159135 T·86.891665ms
11:18:12.797839 table@remove removed @273
11:18:12.798089 table@remove removed @271
11:18:12.798292 table@remove removed @269
11:18:12.798536 table@remove removed @267
11:18:12.798707 table@remove removed @265
11:18:29.015493 memdb@flush N·39878 S·3MiB
11:18:29.081568 memdb@flush created L0@276 N·39878 S·571KiB "stg..ate,v4362105":"stg..ate,v4332420"
11:18:29.081653 version@stat F·[1 1] S·1MiB[571KiB 814KiB] Sc·[0.25 0.01]
11:18:29.083984 memdb@flush committed F·1 T·68.434887ms
11:18:29.084777 journal@remove removed @272
11:18:38.572643 memdb@flush N·43818 S·3MiB
11:18:38.618268 memdb@flush created L0@278 N·43818 S·639KiB "stg..ean,v4399544":"stg..p99,v4379584"
11:18:38.618325 version@stat F·[2 1] S·1MiB[1MiB 814KiB] Sc·[0.50 0.01]
11:18:38.620672 memdb@flush committed F·1 T·47.979173ms
11:18:38.621431 journal@remove removed @275
11:18:57.964063 memdb@flush N·39343 S·3MiB
11:18:58.002823 memdb@flush created L0@280 N·39343 S·587KiB "stg..ean,v4423305":"stg..p99,v4420987"
11:18:58.002877 version@stat F·[3 1] S·2MiB[1MiB 814KiB] Sc·[0.75 0.01]
11:18:58.007657 memdb@flush committed F·1 T·43.545077ms
11:18:58.009019 journal@remove removed @277
11:19:09.512615 memdb@flush N·41156 S·3MiB
11:19:09.573300 memdb@flush created L0@282 N·41156 S·620KiB "car..ime,v4489569":"stg..p99,v4455837"
11:19:09.573353 version@stat F·[4 1] S·3MiB[2MiB 814KiB] Sc·[1.00 0.01]
11:19:09.575644 memdb@flush committed F·1 T·62.995931ms
11:19:09.576553 journal@remove removed @279
11:19:09.576606 table@compaction L0·4 -> L1·1 S·3MiB Q·4500688
11:19:09.681803 table@build created L1@283 N·47011 S·818KiB "car..ize,v4265437":"stg..p99,v4487435"
11:19:09.681862 version@stat F·[0 1] S·818KiB[0B 818KiB] Sc·[0.00 0.01]
11:19:09.684732 table@compaction committed F-4 S-2MiB Ke·0 D·164195 T·108.105552ms
11:19:09.684935 table@remove removed @282
11:19:09.685104 table@remove removed @280
11:19:09.685298 table@remove removed @278
11:19:09.685452 table@remove removed @276
11:19:09.685691 table@remove removed @274
11:19:24.965532 memdb@flush N·43001 S·3MiB
11:19:25.186542 memdb@flush created L0@285 N·43001 S·631KiB "car..hod,v4501180":"stg..p99,v4516557"
11:19:25.186603 version@stat F·[1 1] S·1MiB[631KiB 818KiB] Sc·[0.25 0.01]
11:19:25.189440 memdb@flush committed F·1 T·223.869466ms
11:19:25.190424 journal@remove removed @281
11:19:28.930252 memdb@flush N·42200 S·3MiB
11:19:29.269608 memdb@flush created L0@287 N·42200 S·615KiB "stg..ean,v4569244":"stg..p99,v4567464"
11:19:29.269659 version@stat F·[2 1] S·2MiB[1MiB 818KiB] Sc·[0.50 0.01]
11:19:29.271423 memdb@flush committed F·1 T·341.136243ms
11:19:29.272406 journal@remove removed @284
11:19:35.714425 memdb@flush N·43228 S·3MiB
11:19:35.770520 memdb@flush created L0@289 N·43228 S·640KiB "stg..ean,v4610761":"stg..p99,v4610153"
11:19:35.770565 version@stat F·[3 1] S·2MiB[1MiB 818KiB] Sc·[0.75 0.01]
11:19:35.773121 memdb@flush committed F·1 T·58.647582ms
11:19:35.773783 journal@remove removed @286
11:19:39.468954 memdb@flush N·43169 S·3MiB
11:19:39.514710 memdb@flush created L0@291 N·43169 S·648KiB "stg..ean,v4637276":"stg..p99,v4638276"
11:19:39.514742 version@stat F·[4 1] S·3MiB[2MiB 818KiB] Sc·[1.00 0.01]
11:19:39.518582 memdb@flush committed F·1 T·49.592437ms
11:19:39.519490 journal@remove removed @288
11:19:39.519548 table@compaction L0·4 -> L1·1 S·3MiB Q·4667084
11:19:39.646037 table@build created L1@292 N·47011 S·813KiB "car..ize,v4265437":"stg..p99,v4638276"
11:19:39.646104 version@stat F·[0 1] S·813KiB[0B 813KiB] Sc·[0.00 0.01]
11:19:39.648147 table@compaction committed F-4 S-2MiB Ke·0 D·171598 T·128.577464ms
11:19:39.648391 table@remove removed @291
11:19:39.648554 table@remove removed @289
11:19:39.648794 table@remove removed @287
11:19:39.649056 table@remove removed @285
11:19:39.649339 table@remove removed @283
11:19:48.486155 memdb@flush N·41560 S·3MiB
11:19:48.594255 memdb@flush created L0@294 N·41560 S·613KiB "stg..ean,v4700316":"stg..p99,v4674135"
11:19:48.594311 version@stat F·[1 1] S·1MiB[613KiB 813KiB] Sc·[0.25 0.01]
11:19:48.596261 memdb@flush committed F·1 T·110.045015ms
11:19:48.597191 journal@remove removed @290
11:19:55.838660 memdb@flush N·43373 S·3MiB
11:19:55.887771 memdb@flush created L0@296 N·43373 S·636KiB "stg..ean,v4739198":"stg..p99,v4725356"
11:19:55.887876 version@stat F·[2 1] S·2MiB[1MiB 813KiB] Sc·[0.50 0.01]
11:19:55.889732 memdb@flush committed F·1 T·51.011573ms
11:19:55.890694 journal@remove removed @293
11:19:59.213180 memdb@flush N·39542 S·3MiB
11:19:59.266972 memdb@flush created L0@298 N·39542 S·609KiB "stg..ean,v4759154":"stg..p99,v4757091"
11:19:59.267012 version@stat F·[3 1] S·2MiB[1MiB 813KiB] Sc·[0.75 0.01]
11:19:59.268969 memdb@flush committed F·1 T·55.727792ms
11:19:59.269735 journal@remove removed @295
11:20:08.628714 memdb@flush N·42892 S·3MiB
11:20:08.678536 memdb@flush created L0@300 N·42892 S·632KiB "car..ime,v4805606":"stg..p99,v4794186"
11:20:08.678637 version@stat F·[4 1] S·3MiB[2MiB 813KiB] Sc·[1.00 0.01]
11:20:08.682098 memdb@flush committed F·1 T·53.340046ms
11:20:08.683454 journal@remove removed @297
11:20:08.683518 table@compaction L0·4 -> L1·1 S·3MiB Q·4840636
11:20:08.880420 table@build created L1@301 N·47011 S·818KiB "car..ize,v4265437":"stg..p99,v4823058"
11:20:08.880549 version@stat F·[0 1] S·818KiB[0B 818KiB] Sc·[0.00 0.01]
11:20:08.882696 table@compaction committed F-4 S-2MiB Ke·0 D·167367 T·199.143676ms
11:20:08.883155 table@remove removed @300
11:20:08.883474 table@remove removed @298
11:20:08.883779 table@remove removed @296
11:20:08.884128 table@remove removed @294
11:20:08.884486 table@remove removed @292
11:20:13.323561 memdb@flush N·43408 S·3MiB
11:20:13.372335 memdb@flush created L0@303 N·43408 S·641KiB "dev..ate,v4847235":"stg..p99,v4854400"
11:20:13.372369 version@stat F·[1 1] S·1MiB[641KiB 818KiB] Sc·[0.25 0.01]
11:20:13.375539 memdb@flush committed F·1 T·51.95032ms
11:20:13.376265 journal@remove removed @299
11:20:17.127755 memdb@flush N·43120 S·3MiB
11:20:17.198339 memdb@flush created L0@305 N·43120 S·635KiB "stg..ean,v4897026":"stg..p99,v4881036"
11:20:17.198387 version@stat F·[2 1] S·2MiB[1MiB 818KiB] Sc·[0.50 0.01]
11:20:17.201618 memdb@flush committed F·1 T·73.817043ms
11:20:17.202613 journal@remove removed @302
11:20:20.027397 memdb@flush N·44027 S·3MiB
11:20:20.068276 memdb@flush created L0@307 N·44027 S·631KiB "stg..ean,v4922943":"stg..p99,v4916075"
11:20:20.068323 version@stat F·[3 1] S·2MiB[1MiB 818KiB] Sc·[0.75 0.01]
11:20:20.070968 memdb@flush committed F·1 T·43.539631ms
11:20:20.071902 journal@remove removed @304
11:20:29.321262 memdb@flush N·38499 S·3MiB
11:20:29.414862 memdb@flush created L0@309 N·38499 S·572KiB "stg..ean,v4979956":"stg..p99,v4977626"
11:20:29.414911 version@stat F·[4 1] S·3MiB[2MiB 818KiB] Sc·[1.00 0.01]
11:20:29.418548 memdb@flush committed F·1 T·97.257873ms
11:20:29.419438 journal@remove removed @306
11:20:29.419490 table@compaction L0·4 -> L1·1 S·3MiB Q·5004709
11:20:29.567546 table@build created L1@310 N·47011 S·814KiB "car..ize,v4265437":"stg..p99,v4977626"
11:20:29.567595 version@stat F·[0 1] S·814KiB[0B 814KiB] Sc·[0.00 0.01]
11:20:29.577477 table@compaction committed F-4 S-2MiB Ke·0 D·169054 T·157.963986ms
11:20:29.577708 table@remove removed @309
11:20:29.577876 table@remove removed @307
11:20:29.578102 table@remove removed @305
11:20:29.578298 table@remove removed @303
11:20:29.578505 table@remove removed @301
11:20:37.742421 memdb@flush N·43362 S·3MiB
11:20:38.230693 memdb@flush created L0@312 N·43362 S·657KiB "stg..ean,v5022268":"stg..p99,v5021716"
11:20:38.230762 version@stat F·[1 1] S·1MiB[657KiB 814KiB] Sc·[0.25 0.01]
11:20:38.232808 memdb@flush committed F·1 T·490.34179ms
11:20:38.233584 journal@remove removed @308
11:20:40.038081 memdb@flush N·39243 S·3MiB
11:20:40.070517 memdb@flush created L0@314 N·39243 S·602KiB "stg..ean,v5080490":"stg..p99,v5077799"
11:20:40.070548 version@stat F·[2 1] S·2MiB[1MiB 814KiB] Sc·[0.50 0.01]
11:20:40.072691 memdb@flush committed F·1 T·34.573166ms
11:20:40.073490 journal@remove removed @311
11:20:48.815860 memdb@flush N·40252 S·3MiB
11:20:48.911536 memdb@flush created L0@316 N·40252 S·599KiB "stg..ean,v5120866":"stg..p99,v5109761"
11:20:48.911596 version@stat F·[3 1] S·2MiB[1MiB 814KiB] Sc·[0.75 0.01]
11:20:48.943265 memdb@flush committed F·1 T·127.371533ms
11:20:48.944223 journal@remove removed @313
11:20:58.152653 memdb@flush N·41156 S·3MiB
11:20:58.196125 memdb@flush created L0@318 N·41156 S·620KiB "stg..ean,v5136676":"stg..p99,v5134072"
11:20:58.196186 version@stat F·[4 1] S·3MiB[2MiB 814KiB] Sc·[1.00 0.01]
11:20:58.202713 memdb@flush committed F·1 T·49.996309ms
11:20:58.203870 journal@remove removed @315
11:20:58.203942 table@compaction L0·4 -> L1·1 S·3MiB Q·5167266
11:20:58.406164 table@build created L1@319 N·47011 S·819KiB "car..ize,v4265437":"stg..p99,v5134072"
11:20:58.406219 version@stat F·[0 1] S·819KiB[0B 819KiB] Sc·[0.00 0.01]
11:20:58.407999 table@compaction committed F-4 S-2MiB Ke·0 D·164013 T·204.035076ms
11:20:58.408187 table@remove removed @318
11:20:58.408326 table@remove removed @316
11:20:58.408452 table@remove removed @314
11:20:58.408691 table@remove removed @312
11:20:58.408891 table@remove removed @310
11:21:08.763911 memdb@flush N·42282 S·3MiB
11:21:08.814457 memdb@flush created L0@321 N·42282 S·640KiB "car..ime,v5185289":"stg..p99,v5169025"
11:21:08.814506 version@stat F·[1 1] S·1MiB[640KiB 819KiB] Sc·[0.25 0.01]
11:21:08.838753 memdb@flush committed F·1 T·74.785759ms
11:21:08.839585 journal@remove removed @317
11:21:17.545073 memdb@flush N·43866 S·3MiB
11:21:17.642541 memdb@flush created L0@323 N·43866 S·662KiB "per..ate,v5217761":"stg..p99,v5237085"
11:21:17.642613 version@stat F·[2 1] S·2MiB[1MiB 819KiB] Sc·[0.50 0.01]
11:21:17.662018 memdb@flush committed F·1 T·116.901024ms
11:21:17.662993 journal@remove removed @320
11:21:22.303786 memdb@flush N·41354 S·3MiB
11:21:22.339902 memdb@flush created L0@325 N·41354 S·619KiB "stg..ean,v5278169":"stg..p99,v5277917"
11:21:22.339963 version@stat F·[3 1] S·2MiB[1MiB 819KiB] Sc·[0.75 0.01]
11:21:22.342244 memdb@flush committed F·1 T·38.416779ms
11:21:22.343085 journal@remove removed @322
11:21:30.589519 memdb@flush N·39161 S·3MiB
11:21:30.690539 memdb@flush created L0@327 N·39161 S·603KiB "stg..ean,v5310844":"stg..p99,v5309135"
11:21:30.690594 version@stat F·[4 1] S·3MiB[2MiB 819KiB] Sc·[1.00 0.01]
11:21:30.692685 memdb@flush committed F·1 T·103.092479ms
11:21:30.693310 journal@remove removed @324
11:21:30.693376 table@compaction L0·4 -> L1·1 S·3MiB Q·5338929
11:21:30.826535 table@build created L1@328 N·47011 S·814KiB "car..ize,v4265437":"stg..p99,v5309135"
11:21:30.826618 version@stat F·[0 1] S·814KiB[0B 814KiB] Sc·[0.00 0.01]
11:21:30.828518 table@compaction committed F-4 S-2MiB Ke·0 D·166663 T·135.107464ms
11:21:30.828750 table@remove removed @327
11:21:30.828917 table@remove removed @325
11:21:30.829120 table@remove removed @323
11:21:30.829284 table@remove removed @321
11:21:30.829498 table@remove removed @319
11:21:42.942852 memdb@flush N·43127 S·3MiB
11:21:42.985516 memdb@flush created L0@330 N·43127 S·659KiB "stg..ean,v5342271":"stg..p99,v5340874"
11:21:42.985568 version@stat F·[1 1] S·1MiB[659KiB 814KiB] Sc·[0.25 0.01]
11:21:42.987536 memdb@flush committed F·1 T·44.629728ms
11:21:42.988226 journal@remove removed @326
11:22:02.175643 memdb@flush N·43598 S·3MiB
11:22:02.222243 memdb@flush created L0@332 N·43598 S·659KiB "hes..unt,v5411706":"stg..p99,v5372788"
11:22:02.222308 version@stat F·[2 1] S·2MiB[1MiB 814KiB] Sc·[0.50 0.01]
11:22:02.225605 memdb@flush committed F·1 T·49.897978ms
11:22:02.226978 journal@remove removed @329
11:22:06.148652 memdb@flush N·38911 S·3MiB
11:22:06.199646 memdb@flush created L0@334 N·38911 S·578KiB "car..ime,v5418717":"stg..p99,v5442340"
11:22:06.199683 version@stat F·[3 1] S·2MiB[1MiB 814KiB] Sc·[0.75 0.01]
11:22:06.202924 memdb@flush committed F·1 T·54.228193ms
11:22:06.203619 journal@remove removed @331
11:22:09.601126 memdb@flush N·43717 S·3MiB
11:22:09.669949 memdb@flush created L0@336 N·43717 S·647KiB "dev..ate,v5484645":"stg..p99,v5481760"
11:22:09.670004 version@stat F·[4 1] S·3MiB[2MiB 814KiB] Sc·[1.00 0.01]
11:22:09.671617 memdb@flush committed F·1 T·70.460126ms
11:22:09.672390 journal@remove removed @333
11:22:09.672452 table@compaction L0·4 -> L1·1 S·3MiB Q·5499909
11:22:09.821276 table@build created L1@337 N·47011 S·817KiB "car..ize,v4265437":"stg..p99,v5481760"
11:22:09.821332 version@stat F·[0 1] S·817KiB[0B 817KiB] Sc·[0.00 0.01]
11:22:09.824566 table@compaction committed F-4 S-2MiB Ke·0 D·169353 T·152.081141ms
11:22:09.824813 table@remove removed @336
11:22:09.824980 table@remove removed @334
11:22:09.825162 table@remove removed @332
11:22:09.825287 table@remove removed @330
11:22:09.825450 table@remove removed @328
11:22:23.959331 memdb@flush N·43634 S·3MiB
11:22:24.000912 memdb@flush created L0@339 N·43634 S·665KiB "stg..ean,v5534643":"stg..p99,v5532717"
11:22:24.000997 version@stat F·[1 1] S·1MiB[665KiB 817KiB] Sc·[0.25 0.01]
11:22:24.003177 memdb@flush committed F·1 T·43.788412ms
11:22:24.004340 journal@remove removed @335
11:22:40.683331 memdb@flush N·42043 S·3MiB
11:22:40.715504 memdb@flush created L0@341 N·42043 S·623KiB "stg..ean,v5583303":"stg..p99,v5582044"
11:22:40.715559 version@stat F·[2 1] S·2MiB[1MiB 817KiB] Sc·[0.50 0.01]
11:22:40.718620 memdb@flush committed F·1 T·35.260853ms
11:22:40.719677 journal@remove removed @338
11:22:55.580756 memdb@flush N·43627 S·3MiB
11:22:55.629561 memdb@flush created L0@343 N·43627 S·661KiB "stg..ean,v5620445":"stg..p99,v5618838"
11:22:55.629616 version@stat F·[3 1] S·2MiB[1MiB 817KiB] Sc·[0.75 0.01]
11:22:55.631992 memdb@flush committed F·1 T·51.19474ms
11:22:55.633158 journal@remove removed @340
11:23:08.119825 memdb@flush N·42568 S·3MiB
11:23:08.213793 memdb@flush created L0@345 N·42568 S·650KiB "car..ime,v5670153":"stg..p99,v5650467"
11:23:08.213859 version@stat F·[4 1] S·3MiB[2MiB 817KiB] Sc·[1.00 0.01]
11:23:08.230416 memdb@flush committed F·1 T·110.545527ms
11:23:08.231163 journal@remove removed @342
11:23:08.231231 table@compaction L0·4 -> L1·1 S·3MiB Q·5671654
11:23:08.476692 table@build created L1@346 N·47011 S·819KiB "car..ize,v4265437":"stg..p99,v5650467"
11:23:08.476751 version@stat F·[0 1] S·819KiB[0B 819KiB] Sc·[0.00 0.01]
11:23:08.496693 table@compaction committed F-4 S-2MiB Ke·0 D·171872 T·265.442849ms
11:23:08.496897 table@remove removed @345
11:23:08.497055 table@remove removed @343
11:23:08.497207 table@remove removed @341
11:23:08.497326 table@remove removed @339
11:23:08.497474 table@remove removed @337
11:23:20.228174 memdb@flush N·39915 S·3MiB
11:23:20.270916 memdb@flush created L0@348 N·39915 S·615KiB "mik..ate,v5672387":"stg..p99,v5685542"
11:23:20.270986 version@stat F·[1 1] S·1MiB[615KiB 819KiB] Sc·[0.25 0.01]
11:23:20.272847 memdb@flush committed F·1 T·44.638251ms
11:23:20.273753 journal@remove removed @344
11:23:41.327877 memdb@flush N·43565 S·3MiB
11:23:41.455671 memdb@flush created L0@350 N·43565 S·668KiB "stg..ean,v5750281":"stg..p99,v5716888"
11:23:41.455724 version@stat F·[2 1] S·2MiB[1MiB 819KiB] Sc·[0.50 0.01]
11:23:41.459571 memdb@flush committed F·1 T·131.649165ms
11:23:41.460616 journal@remove removed @347
11:23:55.394825 memdb@flush N·39106 S·3MiB
11:23:55.430987 memdb@flush created L0@352 N·39106 S·592KiB "stg..ean,v5782097":"stg..p99,v5780351"
11:23:55.431049 version@stat F·[3 1] S·2MiB[1MiB 819KiB] Sc·[0.75 0.01]
11:23:55.432908 memdb@flush committed F·1 T·38.026491ms
11:23:55.433937 journal@remove removed @349
11:24:26.156825 memdb@flush N·43340 S·3MiB
11:24:26.202063 memdb@flush created L0@354 N·43340 S·650KiB "stg..ean,v5812619":"stg..p99,v5827895"
11:24:26.202130 version@stat F·[4 1] S·3MiB[2MiB 819KiB] Sc·[1.00 0.01]
11:24:26.203990 memdb@flush committed F·1 T·47.131489ms
11:24:26.206346 journal@remove removed @351
11:24:26.209092 table@compaction L0·4 -> L1·1 S·3MiB Q·5841374
11:24:26.323800 table@build created L1@355 N·47011 S·816KiB "car..ize,v4265437":"stg..p99,v5827895"
11:24:26.323854 version@stat F·[0 1] S·816KiB[0B 816KiB] Sc·[0.00 0.01]
11:24:26.325470 table@compaction committed F-4 S-2MiB Ke·0 D·165926 T·116.351995ms
11:24:26.325677 table@remove removed @354
11:24:26.325809 table@remove removed @352
11:24:26.325969 table@remove removed @350
11:24:26.326112 table@remove removed @348
11:24:26.326275 table@remove removed @346
11:24:38.182689 memdb@flush N·38960 S·3MiB
11:24:38.262790 memdb@flush created L0@357 N·38960 S·604KiB "stg..ean,v5857168":"stg..p99,v5855884"
11:24:38.262836 version@stat F·[1 1] S·1MiB[604KiB 816KiB] Sc·[0.25 0.01]
11:24:38.264802 memdb@flush committed F·1 T·82.075523ms
11:24:38.265475 journal@remove removed @353
11:24:51.710961 memdb@flush N·43328 S·3MiB
11:24:51.815143 memdb@flush created L0@359 N·43328 S·650KiB "stg..ean,v5887863":"stg..p99,v5887120"
11:24:51.815192 version@stat F·[2 1] S·2MiB[1MiB 816KiB] Sc·[0.50 0.01]
11:24:51.817284 memdb@flush committed F·1 T·106.28503ms
11:24:51.817998 journal@remove removed @356
11:25:00.951225 memdb@flush N·40756 S·3MiB
11:25:01.008008 memdb@flush created L0@361 N·40756 S·618KiB "mik..ate,v5958770":"stg..p99,v5919079"
11:25:01.008080 version@stat F·[3 1] S·2MiB[1MiB 816KiB] Sc·[0.75 0.01]
11:25:01.025342 memdb@flush committed F·1 T·74.084776ms
11:25:01.026089 journal@remove removed @358
11:25:09.594415 memdb@flush N·43229 S·3MiB
11:25:10.124767 memdb@flush created L0@363 N·43229 S·659KiB "car..ime,v5989131":"stg..p99,v5983393"
11:25:10.124816 version@stat F·[4 1] S·3MiB[2MiB 816KiB] Sc·[1.00 0.01]
11:25:10.128666 memdb@flush committed F·1 T·534.209443ms
11:25:10.129396 journal@remove removed @360
11:25:10.129522 table@compaction L0·4 -> L1·1 S·3MiB Q·6008532
11:25:10.462829 table@build created L1@364 N·47011 S·814KiB "car..ize,v4265437":"stg..p99,v5983393"
11:25:10.462909 version@stat F·[0 1] S·814KiB[0B 814KiB] Sc·[0.00 0.01]
11:25:10.465748 table@compaction committed F-4 S-2MiB Ke·0 D·166273 T·336.195328ms
11:25:10.477456 table@remove removed @363
11:25:10.477703 table@remove removed @361
11:25:10.477887 table@remove removed @359
11:25:10.478119 table@remove removed @357
11:25:10.478401 table@remove removed @355
11:25:19.737962 memdb@flush N·40626 S·3MiB
11:25:19.778428 memdb@flush created L0@366 N·40626 S·623KiB "dev..ate,v6025486":"stg..p99,v6009012"
11:25:19.778472 version@stat F·[1 1] S·1MiB[623KiB 814KiB] Sc·[0.25 0.01]
11:25:19.781489 memdb@flush committed F·1 T·43.479787ms
11:25:19.782154 journal@remove removed @362
11:25:31.038422 memdb@flush N·43972 S·3MiB
11:25:31.071305 memdb@flush created L0@368 N·43972 S·659KiB "stg..ean,v6080272":"stg..p99,v6071921"
11:25:31.071355 version@stat F·[2 1] S·2MiB[1MiB 814KiB] Sc·[0.50 0.01]
11:25:31.079476 memdb@flush committed F·1 T·41.018258ms
11:25:31.080453 journal@remove removed @365
11:25:50.242729 memdb@flush N·41214 S·3MiB
11:25:50.293248 memdb@flush created L0@370 N·41214 S·616KiB "stg..ean,v6106589":"stg..p99,v6105294"
11:25:50.308280 version@stat F·[3 1] S·2MiB[1MiB 814KiB] Sc·[0.75 0.01]
11:25:50.311718 memdb@flush committed F·1 T·68.89965ms
11:25:50.312641 journal@remove removed @367
11:26:00.506421 memdb@flush N·40546 S·3MiB
11:26:00.597640 memdb@flush created L0@372 N·40546 S·614KiB "per..ate,v6162626":"stg..p99,v6147125"
11:26:00.597702 version@stat F·[4 1] S·3MiB[2MiB 814KiB] Sc·[1.00 0.01]
11:26:00.599741 memdb@flush committed F·1 T·93.282907ms
11:26:00.600365 journal@remove removed @369
11:26:00.600423 table@compaction L0·4 -> L1·1 S·3MiB Q·6174650
11:26:00.730271 table@build created L1@373 N·47011 S·813KiB "car..ize,v4265437":"stg..p99,v6147125"
11:26:00.730350 version@stat F·[0 1] S·813KiB[0B 813KiB] Sc·[0.00 0.01]
11:26:00.732083 table@compaction committed F-4 S-2MiB Ke·0 D·166358 T·131.642748ms
11:26:00.732247 table@remove removed @372
11:26:00.732355 table@remove removed @370
11:26:00.732475 table@remove removed @368
11:26:00.732592 table@remove removed @366
11:26:00.732732 table@remove removed @364
11:26:09.915413 memdb@flush N·40943 S·3MiB
11:26:09.954919 memdb@flush created L0@375 N·40943 S·627KiB "car..ime,v6185795":"stg..p99,v6173980"
11:26:09.954969 version@stat F·[1 1] S·1MiB[627KiB 813KiB] Sc·[0.25 0.01]
11:26:09.958542 memdb@flush committed F·1 T·43.088142ms
11:26:09.959489 journal@remove removed @371
11:26:28.353184 memdb@flush N·43164 S·3MiB
11:26:28.426075 memdb@flush created L0@377 N·43164 S·640KiB "stg..ean,v6247101":"stg..p99,v6244437"
11:26:28.426142 version@stat F·[2 1] S·2MiB[1MiB 813KiB] Sc·[0.50 0.01]
11:26:28.429176 memdb@flush committed F·1 T·51.239457ms
11:26:28.430158 journal@remove removed @374
11:26:40.229671 memdb@flush N·38903 S·3MiB
11:26:40.276405 memdb@flush created L0@379 N·38903 S·597KiB "stg..ean,v6268245":"stg..p99,v6266203"
11:26:40.276471 version@stat F·[3 1] S·2MiB[1MiB 813KiB] Sc·[0.75 0.01]
11:26:40.287126 memdb@flush committed F·1 T·57.412813ms
11:26:40.287754 journal@remove removed @376
11:26:49.922895 memdb@flush N·40165 S·3MiB
11:26:49.965144 memdb@flush created L0@381 N·40165 S·613KiB "stg..ean,v6331650":"stg..p99,v6308456"
11:26:49.965198 version@stat F·[4 1] S·3MiB[2MiB 813KiB] Sc·[1.00 0.01]
11:26:49.966841 memdb@flush committed F·1 T·43.909135ms
11:26:49.967750 journal@remove removed @378
11:26:49.967821 table@compaction L0·4 -> L1·1 S·3MiB Q·6337286
11:26:50.082583 table@build created L1@382 N·47011 S·816KiB "car..ize,v4265437":"stg..p99,v6331063"
11:26:50.082651 version@stat F·[0 1] S·816KiB[0B 816KiB] Sc·[0.00 0.01]
11:26:50.090597 table@compaction committed F-4 S-2MiB Ke·0 D·163175 T·122.744858ms
11:26:50.090818 table@remove removed @381
11:26:50.090946 table@remove removed @379
11:26:50.091090 table@remove removed @377
11:26:50.091217 table@remove removed @375
11:26:50.091373 table@remove removed @373
11:27:01.222578 memdb@flush N·43938 S·3MiB
11:27:01.258387 memdb@flush created L0@384 N·43938 S·652KiB "mik..ate,v6353768":"stg..p99,v6373073"
11:27:01.258441 version@stat F·[1 1] S·1MiB[652KiB 816KiB] Sc·[0.25 0.01]
11:27:01.260126 memdb@flush committed F·1 T·37.51947ms
11:27:01.260863 journal@remove removed @380
11:27:19.131653 memdb@flush N·42614 S·3MiB
11:27:19.181784 memdb@flush created L0@386 N·42614 S·644KiB "car..ime,v6389979":"stg..p99,v6397884"
11:27:19.181862 version@stat F·[2 1] S·2MiB[1MiB 816KiB] Sc·[0.50 0.01]
11:27:19.184286 memdb@flush committed F·1 T·52.472753ms
11:27:19.185296 journal@remove removed @383
11:27:30.052003 memdb@flush N·43015 S·3MiB
11:27:30.089600 memdb@flush created L0@388 N·43015 S·652KiB "stg..ean,v6435306":"stg..p99,v6433741"
11:27:30.089657 version@stat F·[3 1] S·2MiB[1MiB 816KiB] Sc·[0.75 0.01]
11:27:30.091646 memdb@flush committed F·1 T·39.530821ms
11:27:30.093318 journal@remove removed @385
11:27:40.441468 memdb@flush N·43972 S·3MiB
11:27:40.470412 memdb@flush created L0@390 N·43972 S·649KiB "stg..ean,v6503711":"stg..p99,v6491748"
11:27:40.470460 version@stat F·[4 1] S·3MiB[2MiB 816KiB] Sc·[1.00 0.01]
11:27:40.472357 memdb@flush committed F·1 T·30.858299ms
11:27:40.473100 journal@remove removed @387
11:27:40.473155 table@compaction L0·4 -> L1·1 S·3MiB Q·6505742
11:27:40.564109 table@build created L1@391 N·47011 S·812KiB "car..ize,v4265437":"stg..p99,v6491748"
11:27:40.564172 version@stat F·[0 1] S·812KiB[0B 812KiB] Sc·[0.00 0.01]
11:27:40.565907 table@compaction committed F-4 S-2MiB Ke·0 D·173539 T·92.72846ms
11:27:40.566143 table@remove removed @390
11:27:40.566347 table@remove removed @388
11:27:40.566522 table@remove removed @386
11:27:40.566720 table@remove removed @384
11:27:40.566942 table@remove removed @382
11:27:59.303937 memdb@flush N·41634 S·3MiB
11:27:59.336558 memdb@flush created L0@393 N·41634 S·624KiB "stg..ean,v6535562":"stg..p99,v6516851"
11:27:59.336646 version@stat F·[1 1] S·1MiB[624KiB 812KiB] Sc·[0.25 0.01]
11:27:59.338844 memdb@flush committed F·1 T·34.847809ms
11:27:59.340471 journal@remove removed @389
11:28:09.738122 memdb@flush N·43422 S·3MiB
11:28:09.773711 memdb@flush created L0@395 N·43422 S·660KiB "car..ime,v6583161":"stg..p99,v6556251"
11:28:09.773786 version@stat F·[2 1] S·2MiB[1MiB 812KiB] Sc·[0.50 0.01]
11:28:09.775616 memdb@flush committed F·1 T·37.444088ms
11:28:09.776629 journal@remove removed @392

pmap -x 1

1: /usr/bin/go-carbon -daemon=false -config /etc/go-carbon/go-carbon.conf
Address       Kbytes     PSS   Dirty    Swap  Mode  Mapping
0000000000400000    8328    7368       0       0  r-xp  /usr/bin/go-carbon
0000000000c22000    9016    7736       0       0  r--p  /usr/bin/go-carbon
00000000014f0000     432     432     144       0  rw-p  /usr/bin/go-carbon
000000000155c000     280     120     120       0  rw-p    [ anon ]
000000000232d000       4       0       0       0  ---p  [heap]
000000000232e000       4       4       4       0  rw-p  [heap]
000000c000000000    8192    7824    7824       0  rw-p    [ anon ]
000000c000800000 1560576   47104   47104       0  rw-p    [ anon ]
000000c05fc00000  112640  112504  112504       0  rw-p    [ anon ]
000000c066a00000    2048    2048    2048       0  rw-p    [ anon ]
000000c066c00000    2048    2048    2048       0  rw-p    [ anon ]
000000c066e00000    2048    2048    2048       0  rw-p    [ anon ]
000000c067000000   36864   36864   36864       0  rw-p    [ anon ]
000000c069400000    2048    2048    2048       0  rw-p    [ anon ]
000000c069600000 1122304 1122304 1122304       0  rw-p    [ anon ]
000000c0ade00000    2048    2048    2048       0  rw-p    [ anon ]
000000c0ae000000    2048    2048    2048       0  rw-p    [ anon ]
000000c0ae200000    4096    4096    4096       0  rw-p    [ anon ]
000000c0ae600000    2048    2048    2048       0  rw-p    [ anon ]
000000c0ae800000   12288   12288   12288       0  rw-p    [ anon ]
000000c0af400000  239616  239616  239616       0  rw-p    [ anon ]
000000c0bde00000   26624   26624   26624       0  rw-p    [ anon ]
000000c0bf800000  335872  335844  335844       0  rw-p    [ anon ]
000000c0d4000000  210944  210944  210944       0  rw-p    [ anon ]
000000c0e0e00000   10240   10240   10240       0  rw-p    [ anon ]
000000c0e1800000 1662976  641624  641624       0  rw-p    [ anon ]
000000c147000000    2048       0       0       0  rw-p    [ anon ]
000000c147200000   28672    5520    5520       0  rw-p    [ anon ]
000000c148e00000   12288   12288   12288       0  rw-p    [ anon ]
000000c149a00000  165888   16448   16448       0  rw-p    [ anon ]
000000c153c00000   12288   12288   12288       0  rw-p    [ anon ]
000000c154800000    8192       8       8       0  rw-p    [ anon ]
000000c155000000    2048       0       0       0  rw-p    [ anon ]
000000c155200000    6144       0       0       0  rw-p    [ anon ]
000000c155800000    6144       0       0       0  rw-p    [ anon ]
000000c155e00000    4096      16      16       0  rw-p    [ anon ]
000000c156200000    8192       0       0       0  rw-p    [ anon ]
000000c156a00000    8192       0       0       0  rw-p    [ anon ]
000000c157200000    2048       0       0       0  rw-p    [ anon ]
000000c157400000   10240       8       8       0  rw-p    [ anon ]
000000c157e00000    2048       0       0       0  rw-p    [ anon ]
000000c158000000   20480      16      16       0  rw-p    [ anon ]
000000c159400000    2048       0       0       0  rw-p    [ anon ]
000000c159600000   26624      48      48       0  rw-p    [ anon ]
000000c15b000000    2048       0       0       0  rw-p    [ anon ]
000000c15b200000   53248     128     128       0  rw-p    [ anon ]
000000c15e600000    8192       0       0       0  rw-p    [ anon ]
000000c15ee00000    2048       0       0       0  rw-p    [ anon ]
000000c15f000000   16384       0       0       0  rw-p    [ anon ]
000000c160000000    8192       8       8       0  rw-p    [ anon ]
000000c160800000   26624       0       0       0  rw-p    [ anon ]
000000c162200000  104448      24      24       0  rw-p    [ anon ]
000000c168800000   53248       0       0       0  rw-p    [ anon ]
000000c16bc00000    2048       0       0       0  rw-p    [ anon ]
000000c16be00000   26624       0       0       0  rw-p    [ anon ]
000000c16d800000    2048       0       0       0  rw-p    [ anon ]
000000c16da00000   26624       0       0       0  rw-p    [ anon ]
000000c16f400000   67584     528     528       0  rw-p    [ anon ]
000000c173600000    2048       0       0       0  rw-p    [ anon ]
000000c173800000    4096       0       0       0  rw-p    [ anon ]
000000c173c00000    2048       0       0       0  rw-p    [ anon ]
000000c173e00000   12288       0       0       0  rw-p    [ anon ]
000000c174a00000   67584    1576    1576       0  rw-p    [ anon ]
000000c178c00000   26624       0       0       0  rw-p    [ anon ]
000000c17a600000  362496    3536    3536       0  rw-p    [ anon ]
000000c190800000    4096       0       0       0  rw-p    [ anon ]
000000c190c00000    4096       0       0       0  rw-p    [ anon ]
000000c191000000   55296       0       0       0  rw-p    [ anon ]
000000c194600000    2048       0       0       0  rw-p    [ anon ]
000000c194800000    2048       0       0       0  rw-p    [ anon ]
000000c194a00000    2048       0       0       0  rw-p    [ anon ]
000000c194c00000   14336       0       0       0  rw-p    [ anon ]
000000c195a00000    2048      32      32       0  rw-p    [ anon ]
000000c195c00000  110592       0       0       0  rw-p    [ anon ]
000000c19c800000    2048       0       0       0  rw-p    [ anon ]
000000c19ca00000   18432       0       0       0  rw-p    [ anon ]
000000c19dc00000    2048       0       0       0  rw-p    [ anon ]
000000c19de00000   18432       0       0       0  rw-p    [ anon ]
000000c19f000000    6144       0       0       0  rw-p    [ anon ]
000000c19f600000    4096       0       0       0  rw-p    [ anon ]
000000c19fa00000   32768    2024    2024       0  rw-p    [ anon ]
000000c1a1a00000  110592  110592  110592       0  rw-p    [ anon ]
000000c1a8600000    2048     552     552       0  rw-p    [ anon ]
000000c1a8800000   10240       0       0       0  rw-p    [ anon ]
000000c1a9200000    2048       0       0       0  rw-p    [ anon ]
000000c1a9400000    8192       0       0       0  rw-p    [ anon ]
000000c1a9c00000    2048       0       0       0  rw-p    [ anon ]
000000c1a9e00000    4096       0       0       0  rw-p    [ anon ]
000000c1aa200000    6144       0       0       0  rw-p    [ anon ]
000000c1aa800000   14336       0       0       0  rw-p    [ anon ]
000000c1ab600000    2048       0       0       0  rw-p    [ anon ]
000000c1ab800000    4096       0       0       0  rw-p    [ anon ]
000000c1abc00000    2048       0       0       0  rw-p    [ anon ]
000000c1abe00000    4096       0       0       0  rw-p    [ anon ]
000000c1ac200000   14336       8       8       0  rw-p    [ anon ]
000000c1ad000000    4096       0       0       0  rw-p    [ anon ]
000000c1ad400000    4096       0       0       0  rw-p    [ anon ]
000000c1ad800000   40960       0       0       0  ---p    [ anon ]
00007f0958091000  138244  134408  134408       0  rw-p    [ anon ]
00007f096079d000   30616   30512   30512       0  rw-p    [ anon ]
00007f0962583000       8       0       0       0  ---p    [ anon ]
00007f0962585000     132       4       4       0  rw-p    [ anon ]
00007f09625a6000       8       0       0       0  ---p    [ anon ]
00007f09625a8000     132       4       4       0  rw-p    [ anon ]
00007f09625c9000       8       0       0       0  ---p    [ anon ]
00007f09625cb000     132       4       4       0  rw-p    [ anon ]
00007f09625ec000       8       0       0       0  ---p    [ anon ]
00007f09625ee000     132       8       8       0  rw-p    [ anon ]
00007f096260f000       8       0       0       0  ---p    [ anon ]
00007f0962611000     132       8       8       0  rw-p    [ anon ]
00007f0962632000       8       0       0       0  ---p    [ anon ]
00007f0962634000     132       4       4       0  rw-p    [ anon ]
00007f0962655000       8       0       0       0  ---p    [ anon ]
00007f0962657000     132       4       4       0  rw-p    [ anon ]
00007f0962678000       8       0       0       0  ---p    [ anon ]
00007f096267a000   31724   31420   31420       0  rw-p    [ anon ]
00007f096457d000   27036   26832   26832       0  rw-p    [ anon ]
00007f0965fe4000       8       0       0       0  ---p    [ anon ]
00007f0965fe6000   11724   11576   11576       0  rw-p    [ anon ]
00007f0966b64000    4420    4392    4392       0  rw-p    [ anon ]
00007f0966fb5000       8       0       0       0  ---p    [ anon ]
00007f0966fb7000   18200   17996   17996       0  rw-p    [ anon ]
00007f096817f000   14992   14916   14916       0  rw-p    [ anon ]
00007f096902a000    8648    8560    8560       0  rw-p    [ anon ]
00007f09698a6000    7176    7148    7148       0  rw-p    [ anon ]
00007f0969fa9000    4036    4004    4004       0  rw-p    [ anon ]
00007f096a3a0000    3524    3484    3484       0  rw-p    [ anon ]
00007f096a715000    2884    2872    2872       0  rw-p    [ anon ]
00007f096a9ee000   53152   53132   53132       0  rw-p    [ anon ]
00007f096ddd6000       8       0       0       0  ---p    [ anon ]
00007f096ddd8000     388     256     256       0  rw-p    [ anon ]
00007f096de39000       8       0       0       0  ---p    [ anon ]
00007f096de3b000     644     516     516       0  rw-p    [ anon ]
00007f096dedc000       8       0       0       0  ---p    [ anon ]
00007f096dede000     132       4       4       0  rw-p    [ anon ]
00007f096deff000       8       0       0       0  ---p    [ anon ]
00007f096df01000     388     248     248       0  rw-p    [ anon ]
00007f096df62000       8       0       0       0  ---p    [ anon ]
00007f096df64000     132       8       8       0  rw-p    [ anon ]
00007f096df85000       8       0       0       0  ---p    [ anon ]
00007f096df87000    1796    1672    1672       0  rw-p    [ anon ]
00007f096e148000       8       0       0       0  ---p    [ anon ]
00007f096e14a000   37592    2468    2468       0  rw-p    [ anon ]
00007f0970600000    2048       0       0       0  rw-p    [ anon ]
00007f0970800000     652       4       4       0  rw-p    [ anon ]
00007f09708a3000  267748       0       0       0  ---p    [ anon ]
00007f0980e1c000      16      16      16       0  rw-p    [ anon ]
00007f0980e20000  293552       0       0       0  ---p    [ anon ]
00007f0992ccc000       4       4       4       0  rw-p    [ anon ]

bom-d-van commented 1 year ago

or dump a cpu profiling with the golang debug trace tooling and share it, this would give us insight into what the cpu is doing?

Can you elaborate how to do this?

You can refer to this doc about profiling golang programs: https://go.dev/blog/pprof

To enable pprof in go-carbon:

[pprof]
listen = "localhost:7007"
enabled = false

With the cpu and go-routine profile, we might be able to get some hints of what the go program is doing.

for this part, you can refer the online schema migration doc about the current behavior.

however, data in 1h:1y archive should be migrated in your schema changes, can you also share a whisper file with us as a > > reference.

I have read that documentation carefully and was expecting to lose 5m:1d, but not 1h:1y. BTW, what does it mean that temporary file is required when schema changes? Where does it saves that file?

Yes, data in 1h:1y should be migrated. Could you share an original whisper or a migrated whisper file with us, for debugging purpose?

Thank you for clarifying this. Does online-migration-rate mean metric files per second? So, there are some kind of queue for migration files? Does that queue form again in case of go-carbon process restart (assuming there are writes to whisper files)?

Not really, it isn't queued, go-carbon will just skip the file and move on to perform a regular update, but go-carbon would migrate the file when the next updates come if the queue has space. You can check the code here if you are interested: https://github.com/go-graphite/go-carbon/blob/master/persister/whisper.go#L598-L606

hi @auguzun , this seems to be relating to the find/render stat changes you committed 6 months ago (what a long time has it been already!). maybe you want to take a closer look, if you have some spare time?

textPayload: "panic: runtime error: index out of range [0] with length 0

goroutine 114 [running]:
github.com/go-graphite/go-carbon/carbonserver.(*CarbonserverListener).fetchData(0xc0000cc000, {0xc09f245f40, 0x45}, {0xc09f245f40, 0x45}, {0xc091adfd60?, 0x1, 0x4382b3?}, {0xc0b0985779, 0x1, ...}, ...)
    /usr/local/src/go-carbon/carbonserver/render.go:608 +0x978
github.com/go-graphite/go-carbon/carbonserver.(*CarbonserverListener).prepareDataStream(0xc0000cc000, {0xf6f4b8, 0xc0b09b6cc0}, 0x3, 0xc0b09e1140?, 0xc0b0a26db0?, 0xc0b09b71a0)
    /usr/local/src/go-carbon/carbonserver/render.go:442 +0xd17
github.com/go-graphite/go-carbon/carbonserver.(*CarbonserverListener).prepareDataProto.func1()
    /usr/local/src/go-carbon/carbonserver/render.go:489 +0xb3
created by github.com/go-graphite/go-carbon/carbonserver.(*CarbonserverListener).prepareDataProto
    /usr/local/src/go-carbon/carbonserver/render.go:487 +0x4d5"
timestamp: "2023-01-23T08:57:38.255363552Z"

textPayload: "panic: runtime error: index out of range [0] with length 0

goroutine 264 [running]:
github.com/go-graphite/go-carbon/carbonserver.(*CarbonserverListener).fetchData(0xc0004e4380, {0xc06adb2820, 0x45}, {0xc06adb2820, 0x45}, {0xc062c7dc60?, 0x1, 0x4382b3?}, {0xc0630a7693, 0x1, ...}, ...)
    /usr/local/src/go-carbon/carbonserver/render.go:608 +0x978
github.com/go-graphite/go-carbon/carbonserver.(*CarbonserverListener).prepareDataStream(0xc0004e4380, {0xf6f4b8, 0xc09fcb56e0}, 0x3, 0xc0610f8cc0?, 0xc061ccb080?, 0xc09fcb5bc0)
    /usr/local/src/go-carbon/carbonserver/render.go:442 +0xd17
github.com/go-graphite/go-carbon/carbonserver.(*CarbonserverListener).prepareDataProto.func1()
    /usr/local/src/go-carbon/carbonserver/render.go:489 +0xb3
created by github.com/go-graphite/go-carbon/carbonserver.(*CarbonserverListener).prepareDataProto
    /usr/local/src/go-carbon/carbonserver/render.go:487 +0x4d5"
timestamp: "2023-01-23T08:58:00.106458336Z"

Knud3 commented 1 year ago

I did build from persister/online-schema-migration branch and this seems to work (no panics or intensive CPU usage).

I also did investigation where problem might be with metrics. It seems that metrics which have had writes is migrated to 1m:14d,1h:1y as you said, but Grafana panels also include metrics which haven't had writes (even out of selected time range), so it only shows 5m:1d,1h:1y.

metrics

Is there any workaround with this? Other than delete old data files (which haven't had any writes).

~~Also 1h:1y was really loss.~~

~~Is it ok, that I send metric file by email to you @bom-d-van? If that is still relevant.~~

bom-d-van commented 1 year ago

Is there any workaround with this? Other than delete old data files (which haven't had any writes).

yeah, that could be one way to go. I think periodically cleaning up stale whisper files is in general a good practice. you can also manually migrate the schema of those stale whisper files with whisper-resize.py.

I did build from persister/online-schema-migration branch and this seems to work (no panics or intensive CPU usage).

hmm, interesting, there must be some interesting changes committed since then. probably some attentions and loves needed. maybe @timtofan can help. :P

Also 1h:1y was really loss.

Oh, your new schema is 1m:14d,1h:1y (from 5m:1d,1h:1y) and your query is going back only 2 days, which means go-graphite + go-cabron is only returning data from 1m:14d. You need to ask grafana to show data from 14 days ago in order to see the history, like 2023-01-01 - now.

Is it ok, that I send metric file by email to you @bom-d-van? If that is still relevant.

I think it's probably ok to share it here since it's generic system metrics like jvm memory and friends, without the metric names, there isn't a lot of meaning attached to the data saved in the whisper file. but if you prefer, feel free to share it with me through email.

auguzun commented 1 year ago

Hi, @bom-d-van thanks for letting me know, I checked the code and it seems that the broken files caused the panic on carbon restart textPayload: "panic: runtime error: index out of range [0] with length 0 I will fix that panic however the problem with migration remains, I could not reproduce it myself. I will continue digging

bom-d-van commented 1 year ago

thanks for the quick fix, @auguzun . it just occurred to me that the most likely cause is that go-carbon was still building the trie index and falls back to filesystem globing which means that there is no trieNodes returned from trieIndex.query.

I guess booking's instances don't have the problem because no-service-when-index-is-not-ready is enabled (but for a separate reason)?

Knud3 commented 1 year ago

yeah, that could be one way to go. I think periodically cleaning up stale whisper files is in general a good practice. you can also manually migrate the schema of those stale whisper files with whisper-resize.py.

Just cleaning files would be my prefered way to go also, but we have some metrics which team needs for 10 years back (even stales). So automated ways would be nice. Do you have any idea other than deleting or manually run whisper-resize? Or is there any trick for Grafana to not include metrics which are out of time range anyway?

Oh, your new schema is 1m:14d,1h:1y (from 5m:1d,1h:1y) and your query is going back only 2 days, which means go-graphite + go-cabron is only returning data from 1m:14d. You need to ask grafana to show data from 14 days ago in order to see the history, like 2023-01-01 - now.

Good catch. I'm no expert with Grafana nor Carbon. I just try to keep users happy :)

I think it's probably ok to share it here since it's generic system metrics like jvm memory and friends, without the metric names, there isn't a lot of meaning attached to the data saved in the whisper file. but if you prefer, feel free to share it with me through email.

You are right. But I don't know is there anything to share anymore, because everything is more or less clear for now. Thanks to you.

go-graphite / go-carbon

[BUG] Problems with online migration #518