rvagg/node-leveldown — pull request #67 by rvagg (2013-10-12 04:48:01+00:00)
Title: Logging

Exposed the log functionality of leveldb through a `logCallback` option when you call `open()`. If you don't supply a callback then nothing happens so there shouldn't be any perf implications. When you do supply a callback, log entries are formatted and queued in leveldown and when the event loop can handle it, the data is passed to the `logCallback` function as the first argument. See *test/leak-tester.js* for an example of it in action.

Nothing is written to disk, this is all in-memory and queued to the event loop so the perf implications would come mostly in what you end up doing with the log data at the JS end.

Unfortunately this is posix only for now because of the `gettimeofday` stuff but I'm sure it could be easily made cross-platform.

Logging looks like this (minus the 'LOG: ' but at the front), the date is produced by code in *src/log.h* and the unsigned long is the thread id where the event occurred; mostly it'll just be the main leveldb thread.

```
LOG: 2013-10-12 15:38:57.068 139918504376064 Delete type=3 #1
LOG: 2013-10-12 15:38:58.293 139918416275200 Level-0 table #5: started
LOG: 2013-10-12 15:38:58.479 139918416275200 Level-0 table #5: 4179464 bytes OK
LOG: 2013-10-12 15:38:58.480 139918416275200 Delete type=0 #3
LOG: 2013-10-12 15:38:59.267 139918416275200 Level-0 table #7: started
LOG: 2013-10-12 15:38:59.432 139918416275200 Level-0 table #7: 4179510 bytes OK
LOG: 2013-10-12 15:38:59.434 139918416275200 Delete type=0 #4
LOG: 2013-10-12 15:38:59.607 139918416275200 Compacting 1@1 + 1@2 files
LOG: 2013-10-12 15:38:59.702 139918416275200 Generated table #8: 1006 keys, 2127497 bytes
LOG: 2013-10-12 15:38:59.791 139918416275200 Generated table #9: 1006 keys, 2127408 bytes
LOG: 2013-10-12 15:38:59.884 139918416275200 Generated table #10: 1006 keys, 2127431 bytes
LOG: 2013-10-12 15:38:59.884 139918416275200 Level-0 table #12: started
LOG: 2013-10-12 15:39:00.039 139918416275200 Level-0 table #12: 4179565 bytes OK
LOG: 2013-10-12 15:39:00.041 139918416275200 Delete type=0 #6
LOG: 2013-10-12 15:39:00.109 139918416275200 Generated table #13: 934 keys, 1975235 bytes
LOG: 2013-10-12 15:39:00.109 139918416275200 Compacted 1@1 + 1@2 files => 8357571 bytes
LOG: 2013-10-12 15:39:00.110 139918416275200 compacted to: files[ 1 0 4 0 0 0 0 ]
LOG: 2013-10-12 15:39:00.110 139918416275200 Delete type=2 #7
LOG: 2013-10-12 15:39:00.112 139918416275200 Delete type=2 #5
LOG: 2013-10-12 15:39:00.116 139918416275200 Moved #12 to level-1 4179565 bytes OK: files[ 0 1 4 0 0 0 0 ]
LOG: 2013-10-12 15:39:00.273 139918416275200 Compacting 1@1 + 4@2 files
LOG: 2013-10-12 15:39:00.371 139918416275200 Generated table #14: 1006 keys, 2127423 bytes
LOG: 2013-10-12 15:39:00.466 139918416275200 Generated table #15: 1006 keys, 2127406 bytes
LOG: 2013-10-12 15:39:00.482 139918416275200 Level-0 table #18: started
LOG: 2013-10-12 15:39:00.659 139918416275200 Level-0 table #18: 4179539 bytes OK
LOG: 2013-10-12 15:39:00.660 139918416275200 Delete type=0 #11
LOG: 2013-10-12 15:39:00.749 139918416275200 Generated table #17: 1006 keys, 2127364 bytes
LOG: 2013-10-12 15:39:00.849 139918416275200 Generated table #19: 1006 keys, 2127433 bytes
LOG: 2013-10-12 15:39:00.948 139918416275200 Generated table #20: 1006 keys, 2127427 bytes
LOG: 2013-10-12 15:39:01.021 139918416275200 Generated table #21: 898 keys, 1899079 bytes
LOG: 2013-10-12 15:39:01.021 139918416275200 Compacted 1@1 + 4@2 files => 12536132 bytes
LOG: 2013-10-12 15:39:01.023 139918416275200 compacted to: files[ 1 0 6 0 0 0 0 ]
LOG: 2013-10-12 15:39:01.024 139918416275200 Delete type=2 #13
LOG: 2013-10-12 15:39:01.025 139918416275200 Delete type=2 #10
LOG: 2013-10-12 15:39:01.027 139918416275200 Delete type=2 #8
LOG: 2013-10-12 15:39:01.030 139918416275200 Delete type=2 #12
LOG: 2013-10-12 15:39:01.032 139918416275200 Delete type=2 #9
LOG: 2013-10-12 15:39:01.034 139918416275200 Level-0 table #23: started
LOG: 2013-10-12 15:39:01.192 139918416275200 Level-0 table #23: 4179545 bytes OK
LOG: 2013-10-12 15:39:01.193 139918416275200 Delete type=0 #16
LOG: 2013-10-12 15:39:01.413 139918416275200 Compacting 2@0 + 0@1 files
LOG: 2013-10-12 15:39:01.511 139918416275200 Generated table #24: 1006 keys, 2127487 bytes
LOG: 2013-10-12 15:39:01.603 139918416275200 Generated table #25: 1006 keys, 2127417 bytes
LOG: 2013-10-12 15:39:01.691 139918416275200 Generated table #26: 1006 keys, 2127460 bytes
LOG: 2013-10-12 15:39:01.691 139918416275200 Level-0 table #28: started
LOG: 2013-10-12 15:39:01.852 139918416275200 Level-0 table #28: 4179577 bytes OK
LOG: 2013-10-12 15:39:01.853 139918416275200 Delete type=0 #22
LOG: 2013-10-12 15:39:01.921 139918416275200 Generated table #29: 934 keys, 1975194 bytes
LOG: 2013-10-12 15:39:01.921 139918416275200 Compacted 2@0 + 0@1 files => 8357558 bytes
LOG: 2013-10-12 15:39:01.923 139918416275200 compacted to: files[ 1 4 6 0 0 0 0 ]
LOG: 2013-10-12 15:39:01.932 139918416275200 Compacting 1@0 + 4@1 files
LOG: 2013-10-12 15:39:02.026 139918416275200 Generated table #30: 1006 keys, 2127428 bytes
```

This data is fairly predictable and could be parsed to produce an evented logging system so you could watch for certain events, although the events may not quite be verbose enough to help with something like bulk-load optimisation; but ... perhaps someone would be clever enough to make it useful.