Permalink
Browse files

Added some performance logging to the terminus

  • Loading branch information...
1 parent 926638a commit f5872cec912a6a664edf8e0bdd1b1b5eb3c20b8d Ryan Senior committed Feb 21, 2014
@@ -7,9 +7,13 @@ class Puppet::Resource::Catalog::Puppetdb < Puppet::Indirector::REST
include Puppet::Util::Puppetdb::CommandNames
def save(request)
- catalog = munge_catalog(request.instance, extract_extra_request_data(request))
+ msg_idx = rand(10000)
- submit_command(request.key, catalog, CommandReplaceCatalog, 3)
+ catalog = Puppet::Util::Puppetdb.time_and_log("#{msg_idx} - Reformatting catalog for PuppetDB: %s ms",
+ lambda{ munge_catalog(request.instance, extract_extra_request_data(request), msg_idx) })
+
+ Puppet::Util::Puppetdb.time_and_log("#{msg_idx} - Submitting catalog to PuppetDB: %s ms",
+ lambda { submit_command(request.key, catalog, CommandReplaceCatalog, 3, msg_idx) })
end
def find(request)
@@ -23,19 +27,31 @@ def extract_extra_request_data(request)
}
end
- def munge_catalog(catalog, extra_request_data = {})
+ def munge_catalog(catalog, extra_request_data = {}, msg_idx = -1)
hash = catalog.to_pson_data_hash
data = hash['data']
+
+ Puppet::Util::Puppetdb.time_and_log("#{msg_idx} - Addming missing parameters: %s ms",
+ lambda { add_parameters_if_missing(data) })
+
+ Puppet::Util::Puppetdb.time_and_log("#{msg_idx} - Adding namevar aliases: %s ms",
+ lambda { add_namevar_aliases(data, catalog) })
+
+ Puppet::Util::Puppetdb.time_and_log("#{msg_idx} - Stringifying titles: %s ms",
+ lambda { stringify_titles(data) })
+
+ Puppet::Util::Puppetdb.time_and_log("#{msg_idx} - Sorting metaparams: %s ms",
+ lambda { sort_unordered_metaparams(data, msg_idx) })
- add_parameters_if_missing(data)
- add_namevar_aliases(data, catalog)
- stringify_titles(data)
- sort_unordered_metaparams(data)
- munge_edges(data)
- synthesize_edges(data, catalog)
- filter_keys(hash)
- add_transaction_uuid(data, extra_request_data[:transaction_uuid])
+ Puppet::Util::Puppetdb.time_and_log("#{msg_idx} - Munging edges: %s ms",
+ lambda { munge_edges(data, msg_idx) })
+ Puppet::Util::Puppetdb.time_and_log("#{msg_idx} - Synthesizing edges: %s ms",
+ lambda { synthesize_edges(data, catalog) })
+ Puppet::Util::Puppetdb.time_and_log("#{msg_idx} - Filtering keys: %s ms",
+ lambda { filter_keys(hash) })
+ Puppet::Util::Puppetdb.time_and_log("#{msg_idx} - Adding transaction UUID: %s ms",
+ lambda { add_transaction_uuid(data, extra_request_data[:transaction_uuid]) })
hash
end
@@ -112,20 +128,32 @@ def add_namevar_aliases(hash, catalog)
hash
end
- def sort_unordered_metaparams(hash)
+ def sort_unordered_metaparams(hash, msg_idx = -1)
+
+ num_params = 0
+ total_resources = hash['resources'].length
+
hash['resources'].each do |resource|
params = resource['parameters']
+ num_params += params.length
UnorderedMetaparams.each do |metaparam|
if params[metaparam].kind_of? Array then
values = params[metaparam].sort
params[metaparam] = values unless values.empty?
end
end
end
+
+ avg_params = num_params / total_resources
+ Puppet.info("#{msg_idx} - Total number of resources: #{total_resources} - Average number of params: #{avg_params}")
hash
end
- def munge_edges(hash)
+ def munge_edges(hash, msg_idx = -1)
+
+
+ Puppet.info "#{msg_idx} - Number of edges: #{hash['edges'].length}"
+
hash['edges'].each do |edge|
%w[source target].each do |vertex|
edge[vertex] = resource_ref_to_hash(edge[vertex]) if edge[vertex].is_a?(String)
@@ -83,14 +83,7 @@ def run_duration
# term fix is obviously to make the correct data available in puppet.
# I've filed a ticket against puppet here:
# http://projects.puppetlabs.com/issues/16480
- #
- # NOTE: failed reports have an empty metrics hash. Just send 0 for run time,
- # since we don't have access to any better information.
- if metrics["time"] and metrics["time"]["total"]
- metrics["time"]["total"]
- else
- raise Puppet::Error, "Report from #{host} contained no metrics, which is often caused by a failed catalog compilation. Unable to process."
- end
+ metrics["time"]["total"]
end
# Convert an instance of `Puppet::Transaction::Event` to a hash
@@ -58,10 +58,18 @@ def self.to_bool(value)
end
end
+ def self.time_and_log(msg, thunk)
+ before = Time.now
+ result = thunk.call
+ after = Time.now
+ Puppet.info( sprintf(msg, ((after - before) * 1000).round) )
+ result
+ end
+
# @!group Public instance methods
- def submit_command(certname, payload, command_name, version)
- command = Puppet::Util::Puppetdb::Command.new(command_name, version, certname, payload)
+ def submit_command(certname, payload, command_name, version, msg_idx = -1)
+ command = Puppet::Util::Puppetdb::Command.new(command_name, version, certname, payload, msg_idx)
command.submit
end
@@ -19,28 +19,39 @@ class Puppet::Util::Puppetdb::Command
# @param payload Object the payload of the command. This object should be a
# primitive (numeric type, string, array, or hash) that is natively supported
# by JSON serialization / deserialization libraries.
- def initialize(command, version, certname, payload)
+ def initialize(command, version, certname, payload, msg_idx = -1)
@command = command
@version = version
@certname = certname
- @payload = self.class.format_payload(command, version, payload)
+
+ @msg_idx = msg_idx
+ @payload = Puppet::Util::Puppetdb.time_and_log("#{msg_idx} - Creating payload: %s ms",
+ lambda { self.class.format_payload(command, version, payload, msg_idx) })
+
+ Puppet.info( "#{msg_idx} - Message payload length - #{@payload.length}")
+
end
attr_reader :command, :version, :certname, :payload
def submit
checksum = Digest::SHA1.hexdigest(payload)
- escaped_payload = CGI.escape(payload)
+
+ escaped_payload = Puppet::Util::Puppetdb.time_and_log("#{@msg_idx} - Escaping payload: %s ms",
+ lambda { CGI.escape(payload) } )
+
for_whom = " for #{certname}" if certname
begin
http = Puppet::Network::HttpPool.http_instance(config.server, config.port)
- response = http.post(Url, "checksum=#{checksum}&payload=#{escaped_payload}", headers)
+ response = Puppet::Util::Puppetdb.time_and_log("#{@msg_idx} - POSTing payload: %s ms",
+ lambda { http.post(Url, "checksum=#{checksum}&payload=#{escaped_payload}", headers) })
Puppet::Util::Puppetdb.log_x_deprecation_header(response)
if response.is_a? Net::HTTPSuccess
- result = PSON.parse(response.body)
+ result = Puppet::Util::Puppetdb.time_and_log("#{@msg_idx} - Parsing response: %s ms",
+ lambda { PSON.parse(response.body) })
Puppet.info "'#{command}' command#{for_whom} submitted to PuppetDB with UUID #{result['uuid']}"
result
else
@@ -72,14 +83,15 @@ def submit
# @!group Private class methods
# @api private
- def self.format_payload(command, version, payload)
+ def self.format_payload(command, version, payload, msg_idx = 1)
message = {
:command => command,
:version => version,
:payload => payload,
}.to_pson
- Puppet::Util::Puppetdb::CharEncoding.utf8_string(message)
+ Puppet::Util::Puppetdb.time_and_log("#{msg_idx} - Converting to a UTF8 String: %s ms",
+ lambda { Puppet::Util::Puppetdb::CharEncoding.utf8_string(message) })
end
# @!group Private instance methods

0 comments on commit f5872ce

Please sign in to comment.