Skip to content

extensions/time: make to_compact_s 4x faster#81

Merged
bors[bot] merged 3 commits intomasterfrom
to_compact_s-speedup
Apr 11, 2019
Merged

extensions/time: make to_compact_s 4x faster#81
bors[bot] merged 3 commits intomasterfrom
to_compact_s-speedup

Conversation

@unleashed
Copy link
Copy Markdown
Contributor

@unleashed unleashed commented Mar 3, 2019

Time#to_compact_s appears as a hot method in profiling and this should improve its total CPU time.

@mikz
Copy link
Copy Markdown
Contributor

mikz commented Mar 3, 2019

What is slow in the old implementation? strftime or the sub ?

edit: I see #80 which kind of explains it is 50/50.

@unleashed
Copy link
Copy Markdown
Contributor Author

What is slow in the old implementation? strftime or the sub ?

edit: I see #80 which kind of explains it is 50/50.

Yes, kinda. The sub is a bit more expensive in my tests, and using newer Rubies the multiple grows a bit more (seems to imply the VM better optimises the Ruby code vs strftime + sub).

@unleashed unleashed force-pushed the to_compact_s-speedup branch from a0d82ae to 69282ad Compare March 11, 2019 16:04
@davidor
Copy link
Copy Markdown
Contributor

davidor commented Mar 19, 2019

@unleashed this looks good. However, we should add a comment that explains why this was done. Otherwise, other contributors might think that the code is too complicated and revert it back.

I also think that we should document the different in CPU usage in the PR and the commit description.

I measured the difference using the 2.91.1 version. I profiled the worker while processing around 10k jobs. To be clear, this is just CPU time.

Without the patch:

==================================
  Mode: cpu(1000)
  Samples: 3403 (0.00% miss rate)
  GC: 198 (5.82%)
==================================
     TOTAL    (pct)     SAMPLES    (pct)     FRAME
       523  (15.4%)         523  (15.4%)     Hiredis::Ext::Connection#read
       445  (13.1%)         445  (13.1%)     ThreeScale::Backend::TimeHacks#to_compact_s
       225   (6.6%)         225   (6.6%)     Redis::Connection::Hiredis#write
       198   (5.8%)         198   (5.8%)     (garbage collection)
       116   (3.4%)         116   (3.4%)     ThreeScale::Backend::Period::Cache.get
       109   (3.2%)         109   (3.2%)     ThreeScale::Backend::Period::HelperMethods#get_granularity_class
        98   (2.9%)          98   (2.9%)     ThreeScale::Backend::Period::HelperMethods#get_granularity_class
        78   (2.3%)          78   (2.3%)     ThreeScale::Backend::StorageKeyHelpers#encode_key
        67   (2.0%)          67   (2.0%)     ThreeScale::Backend::Period::Boundary::Methods#minute_start
        65   (1.9%)          65   (1.9%)     #<Module:0x0000000001edfc50>.expire_time_for_granularity
       239   (7.0%)          58   (1.7%)     Redis::Namespace#method_missing
        57   (1.7%)          57   (1.7%)     MonitorMixin#mon_enter
        55   (1.6%)          55   (1.6%)     ThreeScale::Backend::Period::Boundary::Methods#week_start
        94   (2.8%)          53   (1.6%)     Redis::Pipeline#call
        52   (1.5%)          52   (1.5%)     ThreeScale::Backend::Period::Boundary::Methods#day_start
      1002  (29.4%)          47   (1.4%)     ThreeScale::Backend::Stats::Aggregators::Base#aggregate_values
        58   (1.7%)          45   (1.3%)     Logger::LogDevice#write
        45   (1.3%)          45   (1.3%)     Yajl::Encoder.encode
        45   (1.3%)          45   (1.3%)     ThreeScale::Backend::Memoizer.fetch
        42   (1.2%)          42   (1.2%)     ThreeScale::Backend::Storage.instance
        41   (1.2%)          41   (1.2%)     Redis::Future#initialize
       331   (9.7%)          40   (1.2%)     ThreeScale::Backend::Stats::Keys#counter_key
        40   (1.2%)          40   (1.2%)     ThreeScale::Backend::Period::HelperMethods#get_granularity_class
        38   (1.1%)          38   (1.1%)     ThreeScale::Backend::Period::Boundary::Methods#hour_start
        33   (1.0%)          33   (1.0%)     Redis::Namespace#clone_args
        60   (1.8%)          30   (0.9%)     ThreeScale::Backend::Transaction#initialize
        29   (0.9%)          29   (0.9%)     MonitorMixin#mon_check_owner
        29   (0.9%)          29   (0.9%)     ThreeScale::Backend::Metric::Collection#sane_value?
        25   (0.7%)          25   (0.7%)     ThreeScale::Backend::Period::Boundary::Methods#year_start
       181   (5.3%)          24   (0.7%)     Redis::Namespace#call_with_namespace

With the patch:

==================================
  Mode: cpu(1000)
  Samples: 4616 (0.00% miss rate)
  GC: 260 (5.63%)
==================================
     TOTAL    (pct)     SAMPLES    (pct)     FRAME
       843  (18.3%)         843  (18.3%)     Hiredis::Ext::Connection#read
       326   (7.1%)         326   (7.1%)     Redis::Connection::Hiredis#write
       260   (5.6%)         260   (5.6%)     (garbage collection)
       197   (4.3%)         197   (4.3%)     ThreeScale::Backend::TimeHacks#to_compact_s
       155   (3.4%)         155   (3.4%)     ThreeScale::Backend::Period::HelperMethods#get_granularity_class
       142   (3.1%)         142   (3.1%)     ThreeScale::Backend::Period::HelperMethods#get_granularity_class
       136   (2.9%)         136   (2.9%)     ThreeScale::Backend::Period::Cache.get
       105   (2.3%)         105   (2.3%)     ThreeScale::Backend::StorageKeyHelpers#encode_key
       102   (2.2%)         102   (2.2%)     ThreeScale::Backend::Period::Boundary::Methods#day_start
       100   (2.2%)         100   (2.2%)     ThreeScale::Backend::Period::Boundary::Methods#minute_start
        95   (2.1%)          95   (2.1%)     MonitorMixin#mon_enter
        88   (1.9%)          88   (1.9%)     #<Module:0x0000000002ccb508>.expire_time_for_granularity
        79   (1.7%)          79   (1.7%)     ThreeScale::Backend::Storage.instance
        94   (2.0%)          79   (1.7%)     Logger::LogDevice#write
        76   (1.6%)          76   (1.6%)     Yajl::Encoder.encode
      1174  (25.4%)          71   (1.5%)     ThreeScale::Backend::Stats::Aggregators::Base#aggregate_values
       118   (2.6%)          70   (1.5%)     Redis::Pipeline#call
        64   (1.4%)          64   (1.4%)     ThreeScale::Backend::Period::Boundary::Methods#week_start
        64   (1.4%)          64   (1.4%)     ThreeScale::Backend::Metric::Collection#sane_value?
       345   (7.5%)          62   (1.3%)     Redis::Namespace#method_missing
        61   (1.3%)          61   (1.3%)     Redis::Namespace#clone_args
        55   (1.2%)          55   (1.2%)     ThreeScale::Backend::Period::Boundary::Methods#hour_start
        55   (1.2%)          55   (1.2%)     ThreeScale::Backend::Period::HelperMethods#get_granularity_class
       169   (3.7%)          54   (1.2%)     ThreeScale::Backend::Stats::Keys#counter_key
        49   (1.1%)          49   (1.1%)     ThreeScale::Backend::Period::Boundary::Methods#month_start
        48   (1.0%)          48   (1.0%)     Redis::Future#initialize
        40   (0.9%)          40   (0.9%)     ThreeScale::Backend::Memoizer.fetch
        82   (1.8%)          38   (0.8%)     ThreeScale::Backend::Metric::Collection#process_parents
        37   (0.8%)          37   (0.8%)     ThreeScale::Backend::StorageKeyHelpers#encode_key
        36   (0.8%)          36   (0.8%)     ThreeScale::Backend::Memoizer.build_args_key

According to this profiling, the time spent in the patched method went from 13.1% to 4.3%.

Comment thread lib/3scale/backend/extensions/time.rb Outdated
# This function is equivalent to:
# strftime('%Y%m%d%H%M%S').sub(/0{0,6}$/, '').
#
# When profiling, we found that this method was one of the ones who
Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

s/who/which

I measured the difference using the 2.91.1 version. I profiled the
worker while processing around 10k jobs. To be clear, this is just CPU
time.

Without the patch:

```
==================================
  Mode: cpu(1000)
  Samples: 3403 (0.00% miss rate)
  GC: 198 (5.82%)
==================================
     TOTAL    (pct)     SAMPLES    (pct)     FRAME
       523  (15.4%)         523  (15.4%)
Hiredis::Ext::Connection#read
       445  (13.1%)         445  (13.1%)
ThreeScale::Backend::TimeHacks#to_compact_s
       225   (6.6%)         225   (6.6%)
Redis::Connection::Hiredis#write
       198   (5.8%)         198   (5.8%)     (garbage collection)
       116   (3.4%)         116   (3.4%)
ThreeScale::Backend::Period::Cache.get
       109   (3.2%)         109   (3.2%)
ThreeScale::Backend::Period::HelperMethods#get_granularity_class
        98   (2.9%)          98   (2.9%)
ThreeScale::Backend::Period::HelperMethods#get_granularity_class
        78   (2.3%)          78   (2.3%)
ThreeScale::Backend::StorageKeyHelpers#encode_key
        67   (2.0%)          67   (2.0%)
ThreeScale::Backend::Period::Boundary::Methods#minute_start
        65   (1.9%)          65   (1.9%)
       239   (7.0%)          58   (1.7%)
Redis::Namespace#method_missing
        57   (1.7%)          57   (1.7%)     MonitorMixin#mon_enter
        55   (1.6%)          55   (1.6%)
ThreeScale::Backend::Period::Boundary::Methods#week_start
        94   (2.8%)          53   (1.6%)     Redis::Pipeline#call
        52   (1.5%)          52   (1.5%)
ThreeScale::Backend::Period::Boundary::Methods#day_start
      1002  (29.4%)          47   (1.4%)
ThreeScale::Backend::Stats::Aggregators::Base#aggregate_values
        58   (1.7%)          45   (1.3%)     Logger::LogDevice#write
        45   (1.3%)          45   (1.3%)     Yajl::Encoder.encode
        45   (1.3%)          45   (1.3%)
ThreeScale::Backend::Memoizer.fetch
        42   (1.2%)          42   (1.2%)
ThreeScale::Backend::Storage.instance
        41   (1.2%)          41   (1.2%)     Redis::Future#initialize
       331   (9.7%)          40   (1.2%)
ThreeScale::Backend::Stats::Keys#counter_key
        40   (1.2%)          40   (1.2%)
ThreeScale::Backend::Period::HelperMethods#get_granularity_class
        38   (1.1%)          38   (1.1%)
ThreeScale::Backend::Period::Boundary::Methods#hour_start
        33   (1.0%)          33   (1.0%)     Redis::Namespace#clone_args
        60   (1.8%)          30   (0.9%)
ThreeScale::Backend::Transaction#initialize
        29   (0.9%)          29   (0.9%)
MonitorMixin#mon_check_owner
        29   (0.9%)          29   (0.9%)
ThreeScale::Backend::Metric::Collection#sane_value?
        25   (0.7%)          25   (0.7%)
ThreeScale::Backend::Period::Boundary::Methods#year_start
       181   (5.3%)          24   (0.7%)
Redis::Namespace#call_with_namespace
```

With the patch:
```
==================================
  Mode: cpu(1000)
  Samples: 4616 (0.00% miss rate)
  GC: 260 (5.63%)
==================================
     TOTAL    (pct)     SAMPLES    (pct)     FRAME
       843  (18.3%)         843  (18.3%)
Hiredis::Ext::Connection#read
       326   (7.1%)         326   (7.1%)
Redis::Connection::Hiredis#write
       260   (5.6%)         260   (5.6%)     (garbage collection)
       197   (4.3%)         197   (4.3%)
ThreeScale::Backend::TimeHacks#to_compact_s
       155   (3.4%)         155   (3.4%)
ThreeScale::Backend::Period::HelperMethods#get_granularity_class
       142   (3.1%)         142   (3.1%)
ThreeScale::Backend::Period::HelperMethods#get_granularity_class
       136   (2.9%)         136   (2.9%)
ThreeScale::Backend::Period::Cache.get
       105   (2.3%)         105   (2.3%)
ThreeScale::Backend::StorageKeyHelpers#encode_key
       102   (2.2%)         102   (2.2%)
ThreeScale::Backend::Period::Boundary::Methods#day_start
       100   (2.2%)         100   (2.2%)
ThreeScale::Backend::Period::Boundary::Methods#minute_start
        95   (2.1%)          95   (2.1%)     MonitorMixin#mon_enter
        88   (1.9%)          88   (1.9%)
        79   (1.7%)          79   (1.7%)
ThreeScale::Backend::Storage.instance
        94   (2.0%)          79   (1.7%)     Logger::LogDevice#write
        76   (1.6%)          76   (1.6%)     Yajl::Encoder.encode
      1174  (25.4%)          71   (1.5%)
ThreeScale::Backend::Stats::Aggregators::Base#aggregate_values
       118   (2.6%)          70   (1.5%)     Redis::Pipeline#call
        64   (1.4%)          64   (1.4%)
ThreeScale::Backend::Period::Boundary::Methods#week_start
        64   (1.4%)          64   (1.4%)
ThreeScale::Backend::Metric::Collection#sane_value?
       345   (7.5%)          62   (1.3%)
Redis::Namespace#method_missing
        61   (1.3%)          61   (1.3%)     Redis::Namespace#clone_args
        55   (1.2%)          55   (1.2%)
ThreeScale::Backend::Period::Boundary::Methods#hour_start
        55   (1.2%)          55   (1.2%)
ThreeScale::Backend::Period::HelperMethods#get_granularity_class
       169   (3.7%)          54   (1.2%)
ThreeScale::Backend::Stats::Keys#counter_key
        49   (1.1%)          49   (1.1%)
ThreeScale::Backend::Period::Boundary::Methods#month_start
        48   (1.0%)          48   (1.0%)     Redis::Future#initialize
        40   (0.9%)          40   (0.9%)
ThreeScale::Backend::Memoizer.fetch
        82   (1.8%)          38   (0.8%)
ThreeScale::Backend::Metric::Collection#process_parents
        37   (0.8%)          37   (0.8%)
ThreeScale::Backend::StorageKeyHelpers#encode_key
        36   (0.8%)          36   (0.8%)
ThreeScale::Backend::Memoizer.build_args_key
```

According to this profiling, the time spent in the patched method went
from 13.1% to 4.3%.
@davidor davidor force-pushed the to_compact_s-speedup branch from 536e146 to 59d179a Compare April 11, 2019 15:27
@unleashed
Copy link
Copy Markdown
Contributor Author

bors r=@davidor

bors Bot added a commit that referenced this pull request Apr 11, 2019
81: extensions/time: make to_compact_s 4x faster r=davidor a=unleashed

`Time#to_compact_s` appears as a hot method in profiling and this should improve its total CPU time.

Co-authored-by: Alejandro Martinez Ruiz <amr@redhat.com>
Co-authored-by: David Ortiz <z.david.ortiz@gmail.com>
@bors
Copy link
Copy Markdown
Contributor

bors Bot commented Apr 11, 2019

Build succeeded

@bors bors Bot merged commit 59d179a into master Apr 11, 2019
@bors bors Bot deleted the to_compact_s-speedup branch April 11, 2019 15:36
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants