Skip to content

Instantly share code, notes, and snippets.

@jsvd

jsvd/3_profile.txt

Last active March 7, 2016 12:41
Show Gist options
  • Save jsvd/a591afa3e2fe6a9aaf22 to your computer and use it in GitHub Desktop.
Save jsvd/a591afa3e2fe6a9aaf22 to your computer and use it in GitHub Desktop.
Download ZIP
Why is grok slow?
Raw
3_profile.txt
% bundle exec ruby -J-Xmx6g --profile bench_slow.rb
Profiling enabled; ^C shutdown will now dump profile info
generating data..done. benchmarking...
Total time: 93.88
%total %self total self children calls name
---------------------------------------------------------------------------------------------------------
0.00 0.00 0.00 1000000/4000001 LogStash::Filters::Grok#match_against_groks
0.00 0.00 0.00 2000000/4000001 LogStash::Filters::Base#filter_matched
0.00 0.00 0.00 1000000/4000001 LogStash::Util::Decorators.add_tags
93.88 0.38 93.50 1/4000001 (top)
100% 0% 93.88 0.38 93.50 4000001 Array#each
93.50 1.55 91.95 1000000/1000000 LogStash::Filters::Grok#filter
77.57 1.28 76.29 1000000/1000000 Grok#match_and_capture
0.06 0.06 0.00 1000000/1000000 String#to_s
---------------------------------------------------------------------------------------------------------
100% 0% 93.88 0.00 93.88 1 (top)
93.88 0.38 93.50 1/4000001 Array#each
---------------------------------------------------------------------------------------------------------
93.50 1.55 91.95 1000000/1000000 Array#each
99% 1% 93.50 1.55 91.95 1000000 LogStash::Filters::Grok#filter
83.53 1.19 82.34 1000000/2000000 Hash#each
4.27 3.97 0.31 2000000/3000000 Cabin::Mixins::Logger.debug?
4.15 2.17 1.98 1000000/1000000 LogStash::Filters::Base#filter_matched
---------------------------------------------------------------------------------------------------------
0.07 0.07 0.00 1000000/2000000 LogStash::Util::Decorators.add_fields
83.53 1.19 82.34 1000000/2000000 LogStash::Filters::Grok#filter
89% 1% 83.60 1.26 82.34 2000000 Hash#each
82.34 0.92 81.42 1000000/1000000 LogStash::Filters::Grok#match
---------------------------------------------------------------------------------------------------------
82.34 0.92 81.42 1000000/1000000 Hash#each
87% 0% 82.34 0.92 81.42 1000000 LogStash::Filters::Grok#match
79.71 0.66 79.05 1000000/1000000 LogStash::Filters::Grok#match_against_groks
1.62 1.62 0.00 1000000/10000000 LogStash::Event#[]
0.09 0.09 0.00 1000000/10000000 Kernel.kind_of?
---------------------------------------------------------------------------------------------------------
79.71 0.66 79.05 1000000/1000000 LogStash::Filters::Grok#match
84% 0% 79.71 0.66 79.05 1000000 LogStash::Filters::Grok#match_against_groks
0.00 0.00 0.00 1000000/4000001 Array#each
---------------------------------------------------------------------------------------------------------
77.57 1.28 76.29 1000000/1000000 Array#each
82% 1% 77.57 1.28 76.29 1000000 Grok#match_and_capture
54.89 4.54 50.35 1000000/11000000 Proc#call
19.48 19.48 0.00 1000000/1000000 Regexp#match
1.92 1.77 0.15 1000000/3000000 Cabin::Mixins::Logger.debug?
---------------------------------------------------------------------------------------------------------
0.00 0.00 0.00 10000000/11000000 Proc#call
54.89 4.54 50.35 1000000/11000000 Grok#match_and_capture
58% 4% 54.89 4.54 50.35 11000000 Proc#call
45.89 21.16 24.73 10000000/10000000 LogStash::Filters::Grok#handle
1.32 1.32 0.00 10000000/10000000 MatchData#[]
0.00 0.00 0.00 10000000/11000000 Proc#call
---------------------------------------------------------------------------------------------------------
45.89 21.16 24.73 10000000/10000000 Proc#call
48% 22% 45.89 21.16 24.73 10000000 LogStash::Filters::Grok#handle
15.58 15.58 0.00 9000000/9000000 LogStash::Event#[]=
6.89 6.89 0.00 9000000/10000000 LogStash::Event#[]
0.49 0.49 0.00 10000000/10000000 NilClass#nil?
0.48 0.48 0.00 9000000/10000000 Kernel.kind_of?
0.47 0.47 0.00 9000000/9000000 Array#include?
0.42 0.42 0.00 9000000/9000000 Kernel.nil?
0.39 0.39 0.00 9000000/9000000 String#empty?
---------------------------------------------------------------------------------------------------------
19.48 19.48 0.00 1000000/1000000 Grok#match_and_capture
20% 20% 19.48 19.48 0.00 1000000 Regexp#match
---------------------------------------------------------------------------------------------------------
15.58 15.58 0.00 9000000/9000000 LogStash::Filters::Grok#handle
16% 16% 15.58 15.58 0.00 9000000 LogStash::Event#[]=
---------------------------------------------------------------------------------------------------------
1.62 1.62 0.00 1000000/10000000 LogStash::Filters::Grok#match
6.89 6.89 0.00 9000000/10000000 LogStash::Filters::Grok#handle
9% 9% 8.51 8.51 0.00 10000000 LogStash::Event#[]
---------------------------------------------------------------------------------------------------------
1.92 1.77 0.15 1000000/3000000 Grok#match_and_capture
4.27 3.97 0.31 2000000/3000000 LogStash::Filters::Grok#filter
6% 6% 6.19 5.73 0.46 3000000 Cabin::Mixins::Logger.debug?
0.46 0.46 0.00 6000000/6000000 Hash#[]
---------------------------------------------------------------------------------------------------------
4.15 2.17 1.98 1000000/1000000 LogStash::Filters::Grok#filter
4% 2% 4.15 2.17 1.98 1000000 LogStash::Filters::Base#filter_matched
0.96 0.96 0.00 2000000/2000000 Module#name
0.46 0.40 0.07 1000000/1000000 LogStash::Util::Decorators.add_fields
0.36 0.30 0.06 1000000/1000000 LogStash::Util::Decorators.add_tags
0.09 0.09 0.00 2000000/2000000 Kernel.class
0.00 0.00 0.00 2000000/4000001 Array#each
---------------------------------------------------------------------------------------------------------
1.32 1.32 0.00 10000000/10000000 Proc#call
1% 1% 1.32 1.32 0.00 10000000 MatchData#[]
---------------------------------------------------------------------------------------------------------
0.96 0.96 0.00 2000000/2000000 LogStash::Filters::Base#filter_matched
1% 1% 0.96 0.96 0.00 2000000 Module#name
---------------------------------------------------------------------------------------------------------
0.09 0.09 0.00 1000000/10000000 LogStash::Filters::Grok#match
0.48 0.48 0.00 9000000/10000000 LogStash::Filters::Grok#handle
0% 0% 0.56 0.56 0.00 10000000 Kernel.kind_of?
---------------------------------------------------------------------------------------------------------
0.49 0.49 0.00 10000000/10000000 LogStash::Filters::Grok#handle
0% 0% 0.49 0.49 0.00 10000000 NilClass#nil?
---------------------------------------------------------------------------------------------------------
0.47 0.47 0.00 9000000/9000000 LogStash::Filters::Grok#handle
0% 0% 0.47 0.47 0.00 9000000 Array#include?
---------------------------------------------------------------------------------------------------------
0.46 0.40 0.07 1000000/1000000 LogStash::Filters::Base#filter_matched
0% 0% 0.46 0.40 0.07 1000000 LogStash::Util::Decorators.add_fields
0.07 0.07 0.00 1000000/2000000 Hash#each
---------------------------------------------------------------------------------------------------------
0.46 0.46 0.00 6000000/6000000 Cabin::Mixins::Logger.debug?
0% 0% 0.46 0.46 0.00 6000000 Hash#[]
---------------------------------------------------------------------------------------------------------
0.42 0.42 0.00 9000000/9000000 LogStash::Filters::Grok#handle
0% 0% 0.42 0.42 0.00 9000000 Kernel.nil?
---------------------------------------------------------------------------------------------------------
0.39 0.39 0.00 9000000/9000000 LogStash::Filters::Grok#handle
0% 0% 0.39 0.39 0.00 9000000 String#empty?
---------------------------------------------------------------------------------------------------------
0.36 0.30 0.06 1000000/1000000 LogStash::Filters::Base#filter_matched
0% 0% 0.36 0.30 0.06 1000000 LogStash::Util::Decorators.add_tags
0.00 0.00 0.00 1000000/4000001 Array#each
---------------------------------------------------------------------------------------------------------
0.09 0.09 0.00 2000000/2000000 LogStash::Filters::Base#filter_matched
0% 0% 0.09 0.09 0.00 2000000 Kernel.class
---------------------------------------------------------------------------------------------------------
0.06 0.06 0.00 1000000/1000000 Array#each
0% 0% 0.06 0.06 0.00 1000000 String#to_s
main profile results:
Total time: 93.88
total self children calls method
----------------------------------------------------------------
93.88 0.38 93.50 4000001 Array#each
93.50 1.55 91.95 1000000 LogStash::Filters::Grok#filter
83.60 1.26 82.34 2000000 Hash#each
82.34 0.92 81.42 1000000 LogStash::Filters::Grok#match
79.71 0.66 79.05 1000000 LogStash::Filters::Grok#match_against_groks
77.57 1.28 76.29 1000000 Grok#match_and_capture
54.89 4.54 50.35 11000000 Proc#call
45.89 21.16 24.73 10000000 LogStash::Filters::Grok#handle
19.48 19.48 0.00 1000000 Regexp#match
15.58 15.58 0.00 9000000 LogStash::Event#[]=
8.51 8.51 0.00 10000000 LogStash::Event#[]
6.19 5.73 0.46 3000000 Cabin::Mixins::Logger.debug?
4.15 2.17 1.98 1000000 LogStash::Filters::Base#filter_matched
1.32 1.32 0.00 10000000 MatchData#[]
0.96 0.96 0.00 2000000 Module#name
0.56 0.56 0.00 10000000 Kernel.kind_of?
0.49 0.49 0.00 10000000 NilClass#nil?
0.47 0.47 0.00 9000000 Array#include?
0.46 0.40 0.07 1000000 LogStash::Util::Decorators.add_fields
0.46 0.46 0.00 6000000 Hash#[]
0.42 0.42 0.00 9000000 Kernel.nil?
0.39 0.39 0.00 9000000 String#empty?
0.36 0.30 0.06 1000000 LogStash::Util::Decorators.add_tags
0.09 0.09 0.00 2000000 Kernel.class
0.06 0.06 0.00 1000000 String#to_s
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment