Last active
May 25, 2017 07:27
-
-
Save sveredyuk/52cfc2b5f7c3fab349de084f3370edde to your computer and use it in GitHub Desktop.
Simple and stupid way how to measure time of code executing
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| # In my current project suddenly occurs a problem. | |
| # One of background job spent too much execution time. | |
| # We are missed of the measurement tool at the begin, so I decide to be a hero that create this tool and | |
| # deliver the answer to a question: "why it takes so much fu#$ing time ?!" | |
| # After 10 minutes of coding I gave birth to this class. | |
| # It's super simple wrapper that measures time spent on coding execution and | |
| # also add some logging feature: | |
| class PerformanceMeter | |
| attr_reader :label, :logger | |
| def initialize(label_name, logger: nil, &block) | |
| @label = label_name || 'meter' | |
| @logger = logger | |
| start | |
| yield(self) | |
| finish | |
| end | |
| def method_missing(meth, *args, &blk) | |
| log!("#{meth}: #{args[0]}") | |
| end | |
| private | |
| attr_reader :start_time, :finish_time, :spent_time | |
| def start | |
| log! "=======> #{label}" | |
| @start_time = Time.now | |
| log! "Start: #{start_time}" | |
| end | |
| def finish | |
| @finish_time = Time.now | |
| @spent_time = finish_time - start_time | |
| log! "Finish: #{finish_time}" | |
| log! "Spent: #{spent_time}" | |
| end | |
| def log!(content) | |
| puts content | |
| logger&.info content | |
| end | |
| end | |
| # Now I can wrap my code with a block, pass a name of measurement and logger object | |
| # also inside block I can call any method on measure object and this add info into the log. | |
| # Very useful for logging some runtime data (names, counters, etc) | |
| PerformanceMeter.new(:my_test, logger: Logger.new('my_test.log')) do |meter| | |
| meter.some_data 'at the begin' | |
| sleep 3 # doing some serious job | |
| meter.some_other_data 'at the end' | |
| end | |
| # And every time when code executing my logs wrote for me something like this: | |
| # my_test.log | |
| # | |
| # I, [2017-05-24T19:22:51.186550 #54150] INFO -- : =======> my_test | |
| # I, [2017-05-24T19:22:51.186964 #54150] INFO -- : Start: 2017-05-24 19:22:51 +0300 | |
| # I, [2017-05-24T19:22:51.187061 #54150] INFO -- : some_data: at the begin | |
| # I, [2017-05-24T19:22:57.191405 #54150] INFO -- : some_other_data: at the end | |
| # I, [2017-05-24T19:22:57.191847 #54150] INFO -- : Finish: 2017-05-24 19:22:57 +0300 | |
| # I, [2017-05-24T19:22:57.192307 #54150] INFO -- : Spent: 3.001977 | |
| # Thank you for reading. Be fast! | |
| # P.S. And yeah.. I fix the project's issue with this measurement tool help and decreae | |
| # executing time form 6 min down to 7 secinds. Yahhooo... | |
| # Maybe I event extract it to the gem if not found something similar | |
| # if you liked such stupid kind of solutions, tweet to me - https://twitter.com/sveredyuk |
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
As a programming exercise it's definitely good :)