Class: Dash::Timings

Inherits:
Object
  • Object
show all
Defined in:
lib/dash/timings.rb

Overview

Wall-clock accounting for a deploy, printed under "Finished all in". The total on its own says nothing about where the time went — a serialised boot, a slow pull, or a proxy waiting on a health check all look the same from the outside.

Entries land in start order and carry a depth, so a parent phase (Boot) prints above the host entries it wraps even though the hosts finish first. Boot runs one thread per host, so every mutation is behind the mutex.

Each entry also accounts for the commands issued while it was the current phase, which is what separates "the boot took 55s" from "the boot spent 41s of that in forty serial SSH round trips". Attribution is by thread-local: phase marks its entry as current for the duration of the block, and lib/dash/sshkit_with_ext.rb stamps every command and every SSH connect onto whatever entry is current on that thread. Nothing extra is executed — dash only measures the round trips it was already making.

Defined Under Namespace

Classes: Entry

Constant Summary collapse

CURRENT_KEY =

The entry the current thread is inside. SSHKit's per-host threads inherit it from the thread that spawned them (see CompleteAll#execute and SSHKitDslRoles#on_roles), so a command issued on a boot thread lands on that host's row.

:dash_timing_entry

Class Method Summary collapse

Instance Method Summary collapse

Constructor Details

#initialize(entries: []) ⇒ Timings

Returns a new instance of Timings.



52
53
54
55
 
# File 'lib/dash/timings.rb', line 52

def initialize(entries: [])
  @entries = entries
  @mutex = Mutex.new
end

Class Method Details

.current_entry ⇒ Object 



27
28
29
 
# File 'lib/dash/timings.rb', line 27

def current_entry
  Thread.current[CURRENT_KEY]
end

.current_entry=(entry) ⇒ Object 



31
32
33
 
# File 'lib/dash/timings.rb', line 31

def current_entry=(entry)
  Thread.current[CURRENT_KEY] = entry
end

.from_h(phases) ⇒ Object

Rebuilds a table from what #to_h exported, so dash report can print a saved deploy the way the deploy printed it. The entries come back parentless: their counters are already the subtree totals #to_h computed, and re-nesting them would roll those totals up a second time.



39
40
41
 
# File 'lib/dash/timings.rb', line 39

def from_h(phases)
  new entries: Array(phases).map { |phase| entry_from(phase.transform_keys(&:to_sym)) }
end

Instance Method Details

#any? ⇒ Boolean

Returns:

  • (Boolean) 


108
109
110
 
# File 'lib/dash/timings.rb', line 108

def any?
  @mutex.synchronize { @entries.any? }
end

#attribute_command(seconds, local:) ⇒ Object 



90
91
92
93
94
95
96
97
98
99
100
 
# File 'lib/dash/timings.rb', line 90

def attribute_command(seconds, local:)
  entry = current or return

  @mutex.synchronize do
    entry.commands += 1
    entry.command_seconds += seconds
    # A phase that issued even one remote command is reported as ssh: the local
    # label is only honest when nothing left the machine.
    entry.local &&= local
  end
end

#attribute_connect(seconds) ⇒ Object 



102
103
104
105
106
 
# File 'lib/dash/timings.rb', line 102

def attribute_connect(seconds)
  entry = current or return

  @mutex.synchronize { entry.connect_seconds += seconds }
end

#current ⇒ Object 



86
87
88
 
# File 'lib/dash/timings.rb', line 86

def current
  self.class.current_entry
end

#entry_at(index) ⇒ Object

Where an entry's row sits in #lines, so Dash::Report can splice its build rows in under the phase they belong to. Identity, not equality: two phases of the same name and duration are equal as Structs but are not the same row. The row at a position, so a consumer that saved an index (Dash::Report, reattaching its build rows to the phase they hung under) can find the entry again.



117
118
119
 
# File 'lib/dash/timings.rb', line 117

def entry_at(index)
  @mutex.synchronize { @entries[index] } if index
end

#index_of(entry) ⇒ Object 



121
122
123
 
# File 'lib/dash/timings.rb', line 121

def index_of(entry)
  @mutex.synchronize { @entries.index { |candidate| candidate.equal?(entry) } }
end

#lines ⇒ Object 



125
126
127
128
129
130
131
 
# File 'lib/dash/timings.rb', line 125

def lines
  with_totals do |entry, totals|
    line = format("  %s%-36s %6.1fs", "  " * entry.depth, entry.name, entry.seconds.to_f)
    line += format(" %3d %-5s %5.1fs", totals[:commands], totals[:local] ? "local" : "ssh", totals[:command_seconds]) if totals[:commands] > 0
    entry.detail ? "#{line} (#{entry.detail})" : line
  end
end

#phase(name, depth: 0) ⇒ Object

Times the block. The entry is yielded so the block can annotate it — a boot can say how long of its total was spent waiting for the container to become healthy.



59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
 
# File 'lib/dash/timings.rb', line 59

def phase(name, depth: 0)
  entry = new_entry(name, depth: depth)
  @mutex.synchronize { @entries << entry }
  started = clock

  previous = self.class.current_entry
  self.class.current_entry = entry

  begin
    yield entry
  ensure
    self.class.current_entry = previous
  end
ensure
  entry.seconds = clock - started
end

#record(name, seconds, depth: 0, detail: nil) ⇒ Object

For time that was measured elsewhere — the gem load and config parse that happened before there was a Timings to record into.



78
79
80
81
82
83
84
 
# File 'lib/dash/timings.rb', line 78

def record(name, seconds, depth: 0, detail: nil)
  new_entry(name, depth: depth).tap do |entry|
    entry.seconds = seconds
    entry.detail = detail
    @mutex.synchronize { @entries << entry }
  end
end

#seconds_for(name) ⇒ Object

A top-level phase's wall time by name, for consumers that know a phase by what it is called rather than by where it sits — the post-deploy hook's build and boot runtimes. Depth-0 only: a per-host row inside Boot is named after the host, but a role could be named "Boot" and must not be mistaken for the phase.



137
138
139
 
# File 'lib/dash/timings.rb', line 137

def seconds_for(name)
  @mutex.synchronize { @entries.find { |entry| entry.name == name && entry.depth.to_i.zero? }&.seconds }
end

#to_h ⇒ Object

The command counts here are subtree totals, matching what the table prints — phases nest, so a consumer must not sum them across depths.



143
144
145
146
147
148
149
150
151
152
153
154
155
156
 
# File 'lib/dash/timings.rb', line 143

def to_h
  with_totals do |entry, totals|
    {
      name: entry.name,
      depth: entry.depth,
      seconds: entry.seconds.to_f,
      detail: entry.detail,
      commands: totals[:commands],
      command_seconds: totals[:command_seconds],
      connect_seconds: totals[:connect_seconds],
      local: totals[:local]
    }
  end
end