Performance characteristics of using Watches for Distributed Task Scheduling

Looking at the transaction log (the test generates 400 MB of logs on the client side!), It looks like this is indeed the case:

Case when a command is already present:

Only one transaction required to get next message.

Transaction #190013 (read/write, 5 operations, '#' = 0.5 ms, started 12:43:28.6200999Z, ended 12:43:28.6341425Z)
┌  oper. ┬──────────────────────────────┬──── start ──── end ── duration ──┬─ sent  recv ┐
│ 0   // │                              │ T+  0.003                        │     -     - │ // WaitForNextCommands(SRV000, 10)
│:0   op │                              │ T+  0.003                        │     -     - │ SetOption PrioritySystemImmediate
│:0   R °│ ##&                          │ T+  0.006 ~   1.481 (  1,475 µs) │    60   163 │ Snapshot.GetRange fGT{(58, 10, "server_commands", "SRV000").<00>} <= k < fGE{(58, 10, "server_commands", "SRV000").<FF>}, limit(10), Exact => 1 result(s)
│ 1   c  │ __`                          │ T+  1.483 ~   1.485 (      2 µs) │    42       │ Clear (58, 10, "server_commands", "SRV000", @164222371293-0#1)
│ 2   Co*│ __`######################### │ T+  1.487 ~  14.059 ( 12,572 µs) │             │ Commit
└────────┴──────────────────────────────┴──────────────────────────────────┴─────────────┘
> Read 163 bytes and Committed 113 bytes in 14.064 ms and 1 attempt(s)

The transaction takes 14ms to read and consume one command from the queue.

Case when a watch must be set up:

First transaction sees nothing, create the watch. When it fires, the transaction is retried and now sees 3 messages.

Transaction #190055 (read/write, 5 operations, '#' = 0.5 ms, started 12:43:28.6451670Z, ended 12:43:28.6471734Z)
┌  oper. ┬──────┬──── start ──── end ── duration ──┬─ sent  recv ┐
│ 0   // │      │ T+  0.002                        │     -     - │ // WaitForNextCommands(SRV000, 10)
│:0   op │      │ T+  0.002                        │     -     - │ SetOption PrioritySystemImmediate
│:0   R °│ ###: │ T+  0.005 ~   1.808 (  1,804 µs) │    60     0 │ Snapshot.GetRange fGT{(58, 10, "server_commands", "SRV000").<00>} <= k < fGE{(58, 10, "server_commands", "SRV000").<FF>}, limit(10), Exact => 0 result(s)
│ 1   W  │ ___` │ T+  1.810                        │     -     - │ Watch (58, 10, "server_commands", "SRV000")
│:1   Co │ ___X │ T+  1.819 ~   2.227 (    409 µs) │             │ Commit
└────────┴──────┴──────────────────────────────────┴─────────────┘
> Completed in 2.231 ms and 1 attempt(s)

// waiting for watch to fire...

Transaction #190087 (read/write, 7 operations, '#' = 0.5 ms, started 12:43:28.6602071Z, ended 12:43:28.6682276Z)
┌  oper. ┬──────────────────┬──── start ──── end ── duration ──┬─ sent  recv ┐
│ 0   // │                  │ T+  0.003                        │     -     - │ // WaitForNextCommands(SRV000, 10)
│:0   op │                  │ T+  0.003                        │     -     - │ SetOption PrioritySystemImmediate
│:0   R °│ ##&              │ T+  0.005 ~   1.551 (  1,546 µs) │    60   489 │ Snapshot.GetRange fGT{(58, 10, "server_commands", "SRV000").<00>} <= k < fGE{(58, 10, "server_commands", "SRV000").<FF>}, limit(10), Exact => 3 result(s)
│ 1   c  │ __`              │ T+  1.553 ~   1.555 (      2 µs) │    42       │ Clear (58, 10, "server_commands", "SRV000", @164222401665-0#1)
│ 2   c  │ __`              │ T+  1.555 ~   1.555 (      1 µs) │    42       │ Clear (58, 10, "server_commands", "SRV000", @164222401753-1#1)
│ 3   c  │ __`              │ T+  1.555 ~   1.556 (      1 µs) │    42       │ Clear (58, 10, "server_commands", "SRV000", @164222401753-2#1)
│ 4   Co°│ __.############# │ T+  1.558 ~   8.449 (  6,892 µs) │             │ Commit
└────────┴──────────────────┴──────────────────────────────────┴─────────────┘
> Read 489 bytes and Committed 339 bytes in 8.455 ms and 1 attempt(s)

For the second case, the transaction that sets up the watch start at xx.6451670. The watch fires at xx.6602071 (15ms later), and the second transaction completes at xx…6682276 (23ms).

These numbers look seems to confirm that indeed the two modes are with and without watch.

1 Like