The following are some results from experiments to determine the relative lack of speed ups from #16809 (pardon the verbosity it's primarily self-documentation). I ran two long running experiments on navy, ycsb -workload F (pure writes) with the same initial-load. From 7/13 04:00 (grafana time) to 7/13 21:11 for the first run (with new changes), second from 7/13 21:27 to 7/14 14:39.

First, the results:

--- Before
17h21m56s       1145.0           0 / 0 / 0        1145 / 0           0 / 0
elapsed__ops/sec(total)__errors(total)
  62516.6s          919.5              0

--- After
17h49m5s       1099.0           0 / 0 / 0        1099 / 0           0 / 0
elapsed__ops/sec(total)__errors(total)
  64145.9s          896.2              0

Overall a 2.59% decrease in throughput. I did the same for a shorter run:

--- Before
1h12m25s       1084.9           0 / 0 / 0        1085 / 0           0 / 0
elapsed__ops/sec(total)__errors(total)
  4345.3s          900.9              0

--- After
1h18m40s       1060.0           0 / 0 / 0        1060 / 0           0 / 0
elapsed__ops/sec(total)__errors(total)
  4720.8s          877.0              0

Similarly, 2.62% decrease in throughput.

Here are some interesting graphs from the longer run, the first half is navy with the dedicated raft engine changes and the second without:

Overall the change, as is, seems to increase Raft command commit latency. Picking navy-006 to remove the outlier:

We have more CGo calls than we did before (this is expected, we're separately committing to a whole another engine without any form of batching across the two):

We have slightly longer raft log processing times:

I tried using go-torch after, here are some flame graphs operating on the same data:

Before:

After:

They both mostly have the same structure (good, expected) except after we have a much wider second flame (I don't know what else to call it).
Looking into this further using callgrind (screenshots not shown) I was able to confirm a larger proportion of time spent in CGo land, happening right about here:

         .          .   4540:   isLogTruncationRequest := rResult.RaftLogDelta != nil
         .      3.62s   4541:   if err := batch.Commit(isLogTruncationRequest); err != nil {
         .          .   4542:           return enginepb.MVCCStats{}, roachpb.NewError(NewReplicaCorruptionError(
         .          .   4543:                   errors.Wrap(err, "could not commit batch")))
         .          .   4544:   }
         .      700ms   4545:   if err := raftBatch.Commit(isLogTruncationRequest); err != nil {
         .          .   4546:           return enginepb.MVCCStats{}, roachpb.NewError(NewReplicaCorruptionError(
         .          .   4547:                   errors.Wrap(err, "could not commit raft batch")))
         .          .   4548:   }
      10ms       10ms   4549:   elapsed := timeutil.Since(start)
         .       30ms   4550:   r.store.metrics.RaftCommandCommitLatency.RecordValue(elapsed.Nanoseconds())
         .       10ms   4551:   return rResult.Delta, nil
         .          .   4552:}
         .          .   4553:

I tried disabling raft log syncing (for both engines, before and after these changes to get a fair comparison) but still saw similar results. As for what I think is happening is our current batching process for RocksDB batch commits. They are specific to individual engines and now that we have two, we batch all writes for the first engine and then separately do the same for the second. This creates this two-phased batching process which might explain the drop in throughput. Compare this to a better batching strategy batching all writes going down to RocksDB, regardless of the engine addressed. Looking into what else can be shared across the two instances, by default the total number of compaction threads are but there probably are more (see include/rocksdb/env.h).

kvserver: separate raft log #16624

Description

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions