Better logging for Google Datastore benchmark

[k1xme]

googledatastore currently output a lot of debugging information via logger to standard output. This makes it incompatible with bencharmark framework PerfKitBenchmark, which relies on parsing standard output to get benchmark results.

Other benchmarks in YCSB have no problem integrate with PKB. So I'm suggesting that we make some changes to the logging code in google datastore.

[kruthar]

@k1xme - sorry don't have a Google Cloud Datastore account set up right at the moment to test this out myself, will get one if necessary. Can you post a little bit of the logging you are referring to? I see that the binding includes log4j, uses a logger in the java class, and has a log4j.properties file in the resources file. Have you tried to fiddle with that?

[k1xme]

@kruthar PKB parse results based on stdout

I ran YCSB googledatastore and redirect stdout to a file and got the following content:

0 [Thread-1] INFO com.yahoo.ycsb.db.GoogleDatastoreClient -Using JWT Service Account credential.
0 [Thread-2] INFO com.yahoo.ycsb.db.GoogleDatastoreClient -Using JWT Service Account credential.
1 [Thread-2] INFO com.yahoo.ycsb.db.GoogleDatastoreClient -DatasetID: database-benchmark, Service Account Email: [email protected], Private Key File Path: /home/kexi/key.p12
0 [Thread-3] INFO com.yahoo.ycsb.db.GoogleDatastoreClient -Using JWT Service Account credential.
1 [Thread-3] INFO com.yahoo.ycsb.db.GoogleDatastoreClient -DatasetID: database-benchmark, Service Account Email: [email protected], Private Key File Path: /home/kexi/key.p12
1 [Thread-1] INFO com.yahoo.ycsb.db.GoogleDatastoreClient -DatasetID: database-benchmark, Service Account Email: [email protected], Private Key File Path: /home/kexi/key.p12
7 [Thread-2] INFO com.yahoo.ycsb.db.GoogleDatastoreClient -Datastore client instance created: com.google.datastore.v1beta3.client.Datastore@35d04d59
7 [Thread-1] INFO com.yahoo.ycsb.db.GoogleDatastoreClient -Datastore client instance created: com.google.datastore.v1beta3.client.Datastore@671ebc67
DBWrapper: report latency for each error is false and specific error codes to track for latency are: []7 [Thread-3] INFO com.yahoo.ycsb.db.GoogleDatastoreClient -Datastore client instance created: com.google.datastore.v1beta3.client.Datastore@99e8a77
DBWrapper: report latency for each error is false and specific error codes to track for latency are: []
DBWrapper: report latency for each error is false and specific error codes to track for latency are: []
[OVERALL], RunTime(ms), 7888.0
[OVERALL], Throughput(ops/sec), 126.77484787018255
[TOTAL_GCS_PS_Scavenge], Count, 1.0
[TOTAL_GC_TIME_PS_Scavenge], Time(ms), 18.0
[TOTAL_GC_TIME_%PS_Scavenge], Time(%), 0.2281947261663286
[TOTAL_GCS_PS_MarkSweep], Count, 0.0
[TOTAL_GC_TIME_PS_MarkSweep], Time(ms), 0.0
[TOTAL_GC_TIME%PS_MarkSweep], Time(%), 0.0
[TOTAL_GCs], Count, 1.0
[TOTAL_GC_TIME], Time(ms), 18.0
[TOTAL_GC_TIME%], Time(%), 0.2281947261663286
[READ], Operations, 945.0
[READ], AverageLatency(us), 19325.67195767196
[READ], MinLatency(us), 8296.0
[READ], MaxLatency(us), 523007.0
[READ], 95thPercentileLatency(us), 63551.0
[READ], 99thPercentileLatency(us), 126207.0
[READ], Return=OK, 945
[CLEANUP], Operations, 3.0
[CLEANUP], AverageLatency(us), 1.3333333333333333
[CLEANUP], MinLatency(us), 1.0
[CLEANUP], MaxLatency(us), 2.0
[CLEANUP], 95thPercentileLatency(us), 2.0
[CLEANUP], 99thPercentileLatency(us), 2.0
[UPDATE], Operations, 55.0
[UPDATE], AverageLatency(us), 59803.490909090906
[UPDATE], MinLatency(us), 28352.0
[UPDATE], MaxLatency(us), 190335.0
[UPDATE], 95thPercentileLatency(us), 125567.0
[UPDATE], 99thPercentileLatency(us), 188799.0
[UPDATE], Return=OK, 55

While PKB was expecting content like

YCSB 0.9.0
Command line: ....
[OVERALL] ......

IMO, information 0 [Thread-1] INFO com.yahoo.ycsb.db.GoogleDatastoreClient -Using JWT Service Account credential. is somewhat unnecessary to output to stdout.

And I'm confused why lines like YCSB 0.9.0 and Command line: ... are output to stderr??

[yuyantingzero]

@k1xme , this is a generic change on YCSB framework IMO, not specific to googledatastore. The reason other benchmarks works fine in PKB is they are currently using 0.7.0 YCSB. 0.9.0 appears to print some logs to stderr.

[k1xme]

@yuyantingzero Yeah, I notice that is a generic change, but I think info should be direct to stdout rather than stderr, which is kinda confused here.

[busbey]

in general, everything should be going to stderr except for the result exporter. unfortunately, #240 and #241 are still open so we aren't consistent across modules. YCSB core should be doing the correct thing. FWICT, the output you're referring to comes from the log4j properties shipped in the binding for Google Datastore:

https://github.com/brianfrankcooper/YCSB/blob/0.9.0/googledatastore/src/main/resources/log4j.properties#L17

The ConsoleAppender by default goes to stdout. If you update the configuration (by either modifying the above file or passing your own copy on the classpath) you can have it write to stderr

#define the console appender
log4j.appender.consoleAppender = org.apache.log4j.ConsoleAppender
# Non-test-result output goes to stderr
log4j.appender.consoleAppender.Target=System.err

# now define the layout for the appender
log4j.appender.consoleAppender.layout = org.apache.log4j.PatternLayout
log4j.appender.consoleAppender.layout.ConversionPattern=%-4r [%t] %-5p %c %x -%m%n

# now map our console appender as a root logger, means all log messages will go
# to this appender
log4j.rootLogger = INFO, consoleAppender

[k1xme]

@busbey Thank you for the information! Good to know that. Yeah, then I think the changes should be made on PKB side, not YCSB.

[busbey]

thanks for following up! if it turns out changing it on PKB is prohibitive, I'd be happy to have our default log4j setting changed to use stderr. Just reopen this issue.