# Performance characteristics of using Watches for Distributed Task Scheduling

**URL:** <https://forums.foundationdb.org/t/performance-characteristics-of-using-watches-for-distributed-task-scheduling/471>\
**Category:** FoundationDB Layers\
**Tags:** performance\
**Created:** [May 24, 2018, 1:42pm UTC](https://forums.foundationdb.org/t/performance-characteristics-of-using-watches-for-distributed-task-scheduling/471 "2018-05-24T13:42:28Z")\
**Posts on this page:** 1\
**Showing post:** 25

<div class="post-metadata">

**Author:** ![KrzysFR](https://sea1.discourse-cdn.com/foundationdb/user_avatar/forums.foundationdb.org/krzysfr/32/43_2.png) [@KrzysFR](https://forums.foundationdb.org/u/KrzysFR)\
**Post date:** [June 16, 2018, 12:53pm UTC](https://forums.foundationdb.org/t/performance-characteristics-of-using-watches-for-distributed-task-scheduling/471/25 "2018-06-16T12:53:14Z")

</div>

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.

```auto
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.

```auto
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.

---

_[View the full topic](https://forums.foundationdb.org/t/performance-characteristics-of-using-watches-for-distributed-task-scheduling/471)._