Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Spec: show time in human friendly way in --profile #2875

Merged
merged 1 commit into from
Jun 21, 2016
Merged

Spec: show time in human friendly way in --profile #2875

merged 1 commit into from
Jun 21, 2016
+32 −13

Conversation

asterite
Copy link
Member

Before:

$ crystal spec spec/std/int_spec.cr --profile
...

Int compares signed vs. unsigned integers : 0.000459 sec
Int ** raises with negative exponent : 4.3e-05 sec
Int to_s in base raises on base 1 : 1.2e-05 sec
Int ** with float assert : 1.1e-05 sec
Int to_s does to_s for various int sizes with IO : 1.1e-05 sec
Int to_s does to_s for various int sizes : 1.0e-05 sec
Int #chr : 1.0e-05 sec
Int ** with positive Int32 : 9.0e-06 sec
Int to_s in base raises on base 37 with io : 7.0e-06 sec
Int to_s in base raises on base 1 with io : 7.0e-06 sec
Int raises when divides by zero : 7.0e-06 sec

Finished in 1.92 milliseconds
141 examples, 0 failures, 0 errors, 0 pending

After:

$ bin/crystal spec spec/std/int_spec.cr --profile
...

Int ** raises with negative exponent : 34 microseconds
Int compares signed vs. unsigned integers : 33 microseconds
Int to_s in base raises on base 1 : 11 microseconds
Int to_s does to_s for various int sizes with IO : 10 microseconds
Int to_s does to_s for various int sizes : 9 microseconds
Int ** with positive Int32 : 9 microseconds
Int to_s in base raises on base 37 with io : 8 microseconds
Int ** with float assert : 8 microseconds
Int to_s in base raises on base 62 with upcase with io : 7 microseconds
Int to_s in base raises on base 1 with io : 7 microseconds
Int #chr : 7 microseconds

Finished in 1.4 milliseconds
141 examples, 0 failures, 0 errors, 0 pending

@jhass
Copy link
Member

jhass commented Jun 18, 2016

Mmh, I'm actually not too sure this is the easiest to read, vs determining the maximum, the unit to represent it as integer and representing all others as fractions of that unit.

@asterite
Copy link
Member Author

asterite commented Jun 18, 2016 •
edited
Loading

I don't know if it matters much, the comparison between spec times, only how long they take. For example:

$ bin/crystal spec spec/std/crypto/* --profile
.............

Crypto::Bcrypt computes digest vectors : 2.69 seconds
Crypto::Blowfish encrypt and decrypt pair : 32.27 milliseconds
...

Reading "seconds" vs "milliseconds" is already clear there's a huge difference. Showing the second as 0.03227 seconds could work, though it would be a lot more noisy in my opinion.

@asterite
Copy link
Member Author

@jhass after some though, I think normalizing the unit is probably a good idea. This is RSpec's output for --profile:

Top 10 slowest examples (0.03766 seconds, 38.7% of total time):
  Rgviz::Parser parses options
    0.02435 seconds ./spec/rgviz/parser_spec.rb:330
  Rgviz::Lexer lexes or upcase
    0.0039 seconds ./spec/rgviz/lexer_spec.rb:13
  Rgviz::Lexer lexes and
    0.00246 seconds ./spec/rgviz/lexer_spec.rb:7
  Rgviz::MemoryExecutor processes group by with scalar
    0.00176 seconds ./spec/rgviz/memory_executor_spec.rb:293
  Rgviz::Parser parses empty
    0.00132 seconds ./spec/rgviz/parser_spec.rb:47
  Rgviz::Lexer lexes error !
    0.00114 seconds ./spec/rgviz/lexer_spec.rb:73
  Rgviz::MemoryExecutor processes select date "2010-01-02"
    0.00075 seconds ./spec/rgviz/memory_executor_spec.rb:23
  Rgviz::MemoryExecutor processes pivot
    0.00072 seconds ./spec/rgviz/memory_executor_spec.rb:394
  Rgviz::MemoryExecutor processes pivot2
    0.00064 seconds ./spec/rgviz/memory_executor_spec.rb:432
  Rgviz::CsvRenderer renders two rows
    0.00062 seconds ./spec/rgviz/csv_renderer_spec.rb:6

Top 4 slowest example groups:
  Rgviz::CsvRenderer
    0.00078 seconds average (0.00078 seconds / 1 example) ./spec/rgviz/csv_renderer_spec.rb:5
  Rgviz::Parser
    0.00039 seconds average (0.04724 seconds / 122 examples) ./spec/rgviz/parser_spec.rb:5
  Rgviz::MemoryExecutor
    0.00032 seconds average (0.0239 seconds / 74 examples) ./spec/rgviz/memory_executor_spec.rb:5
  Rgviz::Lexer
    0.00018 seconds average (0.02503 seconds / 140 examples) ./spec/rgviz/lexer_spec.rb:5

I like it that the seconds are all more or less aligned, and that you can quickly see where the spec is defined. The "slowest example groups" is nice too, but we can leave that for later.

@asterite asterite force-pushed the feature/spec_human_time branch from 80b0024 to af4b420 Compare June 20, 2016 21:41
@asterite asterite force-pushed the feature/spec_human_time branch from af4b420 to 3c0fc5b Compare June 20, 2016 21:46
@asterite
Copy link
Member Author

I thought I commented this before... seems not.

With the last change, the output now looks like this:

$ bin/crystal spec spec/std/int_spec.cr --profile
...

Top 10 slowest examples (0.00021 seconds, 13.98% of total time):
  Int compares signed vs. unsigned integers
    4.0e-05 seconds ./spec/std/int_spec.cr:417
  Int ** raises with negative exponent
    3.4e-05 seconds ./spec/std/int_spec.cr:30
  Int raises when divides by zero
    3.3e-05 seconds ./spec/std/int_spec.cr:325
  Int raises when mods by zero
    2.6e-05 seconds ./spec/std/int_spec.cr:330
  Int #popcount assert
    2.1e-05 seconds ./spec/std/int_spec.cr:404
  Int to_s does to_s for various int sizes with IO
    1.1e-05 seconds ./spec/std/int_spec.cr:267
  Int to_s in base raises on base 1
    1.0e-05 seconds ./spec/std/int_spec.cr:131
  Int to_s does to_s for various int sizes
    9.0e-06 seconds ./spec/std/int_spec.cr:244
  Int #chr
    9.0e-06 seconds ./spec/std/int_spec.cr:441
  Int ** with positive Int32
    9.0e-06 seconds ./spec/std/int_spec.cr:14
  Int gets times iterator
    7.0e-06 seconds ./spec/std/int_spec.cr:335

Finished in 1.5 milliseconds
141 examples, 0 failures, 0 errors, 0 pending

I think that's good enough, even with those "e-05", which can be read as "too fast, don't pay attention to this".

@asterite asterite merged commit 348ed3f into release/0.18 Jun 21, 2016
@jhass jhass added this to the 0.18.3 milestone Jun 21, 2016
@jhass jhass mentioned this pull request Aug 22, 2016
Closed
@asterite asterite deleted the feature/spec_human_time branch April 27, 2018 21:23
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers
No reviews
Assignees
No one assigned
Labels
topic:stdlib
Projects
None yet
Milestone
0.18.3
Development

Successfully merging this pull request may close these issues.

None yet
2 participants
@asterite @jhass