 |
Forums |
Admin Discussion Forums: help Start New Thread
By: Adam Pisoni
 RE: SkynetDebugger speed issue [ reply ]
2008-06-03 23:07
|
Wow, thanks for finding that. I'm thinking that the actual slowness is coming from that message.to_a. What happens when you remove that from the end of the second debug?
It may be that we have to move towards some constant for some of those heavier debug statements. The problem is, that line IS being executed on every pass, it's just that the message isn't being written to the log unless you're in debug mode.
Also, there's a handy printlog command you can use instead of debug if you want to ALWAYS print something regardless of the loglevel.
|
By: Sean Jones
SkynetDebugger speed issue [ reply ]
2008-06-03 21:02
|
In skynet_job.rb @ line 418, I hacked in a quick timer (I'm sure there is a better way to do this in Ruby).
def enqueue_messages(messages)
size = messages.size
messages.each_with_index do |message,ii|
timeout = message.expiry || 5
ta=Time.new
debug "RUN TASKS SUBMITTING #{message.name} job_id: #{job_id} #{message.payload.is_a?(Skynet::Task) ? 'task' + message.payload.task_id.to_s : ''}"
debug "RUN TASKS WORKER MESSAGE #{message.name} job_id: #{job_id}", message.to_a
tb=Time.new
ab = tb.to_f - ta.to_f
error "debug calls took: " + ab.to_s + " seconds"
mq.write_message(message,timeout * 5)
info "write_message complete"
end
end
The results in skynet.log look like this:
[ERROR] #32418 2008-06-03 13:41:12.162611 <JOB> debug calls took: 3.20812201499939 seconds
[ERROR] #32418 2008-06-03 13:41:18.360987 <JOB> debug calls took: 3.61134195327759 seconds
[ERROR] #32418 2008-06-03 13:41:21.946874 <JOB> debug calls took: 2.04486513137817 seconds
[ERROR] #32418 2008-06-03 13:41:25.415762 <JOB> debug calls took: 1.91745400428772 seconds
[ERROR] #32418 2008-06-03 13:41:28.825269 <JOB> debug calls took: 1.91528606414795 seconds
If I comment those two debug lines, I get the following results (notice the e-06).
[ERROR] #32464 2008-06-03 13:41:52.389407 <JOB> debug calls took: 3.09944152832031e-06 seconds
[ERROR] #32464 2008-06-03 13:41:53.872251 <JOB> debug calls took: 9.5367431640625e-07 seconds
[ERROR] #32464 2008-06-03 13:41:55.553286 <JOB> debug calls took: 9.5367431640625e-07 seconds
[ERROR] #32464 2008-06-03 13:41:57.299358 <JOB> debug calls took: 1.9073486328125e-06 seconds
[ERROR] #32464 2008-06-03 13:41:59.189676 <JOB> debug calls took: 1.19209289550781e-06 seconds
Seems like those two are very slow. Those two calls alone add ~2 seconds to my job submission. Any ideas on how that can be improved? I'd rather not go thru and remove all the debug messages, since I like that functionality.
Sean
|
|
|
