diff options
| author | Tim Smith <tsmith@chef.io> | 2017-09-11 09:21:53 -0700 |
|---|---|---|
| committer | Tim Smith <tsmith@chef.io> | 2017-09-11 09:21:53 -0700 |
| commit | ca251057334898a5cd4c19b4d91d10c7f9ca84a6 (patch) | |
| tree | 6396f26da0da93e010051d64250d423feb29276e | |
| parent | 1faa4ba02326914e6e81506f090ebce14fea291e (diff) | |
| download | ohai-timing.tar.gz | |
Add plugin timing information in debug modetiming
A reoccurring problem in Ohai is the runs taking too long. It's hard to troubleshoot since you can't tell what plugin is causing the long runs. This simple debug information provides us with the information we need to troubleshoot unusually long ohai run times.
Example output
```
[2017-09-11T09:20:27-07:00] DEBUG: Plugin Ruby took 1.568772 seconds to run.
[2017-09-11T09:20:27-07:00] DEBUG: Plugin Rust: ran 'rustc --version' and returned 0
[2017-09-11T09:20:27-07:00] DEBUG: Plugin Rust took 0.356488 seconds to run.
[2017-09-11T09:20:31-07:00] DEBUG: Plugin Scala: ran 'scala -version' and returned 0
[2017-09-11T09:20:31-07:00] DEBUG: Plugin Scala took 3.216373 seconds to run.
[2017-09-11T09:20:36-07:00] DEBUG: Ohai took 16.940469 total seconds to run.
```
Signed-off-by: Tim Smith <tsmith@chef.io>
| -rw-r--r-- | lib/ohai/application.rb | 3 | ||||
| -rw-r--r-- | lib/ohai/runner.rb | 3 |
2 files changed, 6 insertions, 0 deletions
diff --git a/lib/ohai/application.rb b/lib/ohai/application.rb index 586a275d..51ba6433 100644 --- a/lib/ohai/application.rb +++ b/lib/ohai/application.rb @@ -20,6 +20,7 @@ require "chef-config/workstation_config_loader" require "ohai" require "ohai/log" require "mixlib/cli" +require "time" class Ohai::Application include Mixlib::CLI @@ -74,8 +75,10 @@ class Ohai::Application end def run + start_time = Time.now configure_ohai run_application + Ohai::Log.debug("Ohai took #{Time.now - start_time} total seconds to run.") end def configure_ohai diff --git a/lib/ohai/runner.rb b/lib/ohai/runner.rb index 93ec46a3..87a3f1d8 100644 --- a/lib/ohai/runner.rb +++ b/lib/ohai/runner.rb @@ -18,6 +18,7 @@ # require "ohai/dsl" +require "time" module Ohai class Runner @@ -33,6 +34,7 @@ module Ohai # If force is set to true, then this plugin and its dependencies # will be run even if they have been run before. def run_plugin(plugin) + start_time = Time.now unless plugin.kind_of?(Ohai::DSL::Plugin) raise Ohai::Exceptions::InvalidPlugin, "Invalid plugin #{plugin} (must be an Ohai::DSL::Plugin or subclass)" end @@ -53,6 +55,7 @@ module Ohai rescue Exception, Errno::ENOENT => e Ohai::Log.debug("Plugin #{plugin.name} threw exception #{e.inspect} #{e.backtrace.join("\n")}") end + Ohai::Log.debug("Plugin #{plugin.name} took #{Time.now - start_time} seconds to run.") end def run_v6_plugin(plugin) |