From: Charles Mills <cmills@...>
Date: 2005-01-13T07:26:17+09:00
Subject: Re: optparse


Daniel Berger wrote:
> Does running it through the profiler provide any insight?
> As to your other question, I'm afraid I just don't know.
>

So I ran it through the profiler and the last line below jumped out at
me.

%   cumulative   self              self     total
time   seconds   seconds    calls  ms/call  ms/call  name
12.22     5.00      5.00     3759     1.33     3.38
Preprocessor::Tokens#shift
11.78     9.82      4.82     4055     1.19     1.58
CTokenizer::Lexer#shift
6.38    12.43      2.61      667     3.91    10.69  Array#each
4.25    14.17      1.74    21566     0.08     0.08  Array#at
4.23    15.90      1.73     1553     1.11     1.62
CTokenizer::Scoped.process_scope
4.06    17.56      1.66     1550     1.07    14.74  Kernel.loop
3.72    19.08      1.52    20222     0.08     0.08  Kernel.==
3.08    20.34      1.26     1483     0.85    19.82  DBC::Parser#shift
2.86    21.51      1.17     1553     0.75    16.37
Preprocessor::Parser#shift
2.76    22.64      1.13      383     2.95   127.36
Racc::Parser#_racc_do_parse_c
(...)
0.15    38.69      0.06       13     4.62    43.08
OptionParser#make_switch
0.15    38.75      0.06       50     1.20     1.80
CType::Parser#_reduce_113
0.12    38.80      0.05       81     0.62     0.62
CTokenizer::Splitter#reset
0.12    38.85      0.05      302     0.17     0.33
Preprocessor::Parser#_reduce_1
0.12    38.90      0.05      122     0.41     0.41  Hash#include?
0.12    38.95      0.05      366     0.14     0.14  Hash#[]=
0.12    39.00      0.05      105     0.48     1.62
CTokenizer::Splitter#shift
0.12    39.05      0.05       38     1.32     1.32  Hash#invert
0.12    39.10      0.05       54     0.93     4.81
Array#reverse_each
0.12    39.15      0.05      135     0.37     0.37
CType::Parser#_reduce_114
0.12    39.20      0.05      135     0.37     1.48
CType::Parser#_reduce_116
0.12    39.25      0.05      556     0.09     0.09  Array#<<
0.10    39.29      0.04       76     0.53    34.74
Preprocessor::Parser#_reduce_9
0.10    39.33      0.04       58     0.69     0.69
CType::Parser#_reduce_165
0.10    39.37      0.04       19     2.11    11.58
OptionParser::List#update
0.10    39.41      0.04        1    40.00   820.00
OptionParser#initialize
(...)

It may just be optparse creates more objects causing the GC to run more
often.

-Charlie