On Wed, 18 Aug 2010 21:05:34 -0400, Walter Bright <newshound2@digitalmars.com> wrote:

> http://www.drdobbs.com/blog/archives/2010/08/c_compilation_s.html
>
> I'll be doing a followup on why D compiles fast.

Very interesting stuff.

I'd like to have an article describing how to diagnose slow D compilation :P

Dcollections with unit tests compiles in over a minute, with I think about 12 files that contain implementation.  I estimate probably 5000 loc.

-Steve

Steven Schveighoffer wrote:
> On Wed, 18 Aug 2010 21:05:34 -0400, Walter Bright <newshound2@digitalmars.com> wrote:
> 
>> http://www.drdobbs.com/blog/archives/2010/08/c_compilation_s.html
>>
>> I'll be doing a followup on why D compiles fast.
> 
> Very interesting stuff.
> 
> I'd like to have an article describing how to diagnose slow D compilation :P
> 
> Dcollections with unit tests compiles in over a minute, with I think about 12 files that contain implementation.  I estimate probably 5000 loc.

You can start with -v.

On Mon, 23 Aug 2010 12:44:50 -0400, Walter Bright <newshound2@digitalmars.com> wrote:

> Steven Schveighoffer wrote:
>> On Wed, 18 Aug 2010 21:05:34 -0400, Walter Bright <newshound2@digitalmars.com> wrote:
>>
>>> http://www.drdobbs.com/blog/archives/2010/08/c_compilation_s.html
>>>
>>> I'll be doing a followup on why D compiles fast.
>>  Very interesting stuff.
>>  I'd like to have an article describing how to diagnose slow D compilation :P
>>  Dcollections with unit tests compiles in over a minute, with I think about 12 files that contain implementation.  I estimate probably 5000 loc.
>
> You can start with -v.

I get a long list of functions proceeding at a reasonable rate.  I've done that in the past, I feel it's some sort of inner loop problem.  Essentially, something takes way longer to compile than it should, but way longer on the order of .05 seconds instead of .005 seconds, so you don't notice it normally.  But somehow my library is able to harness that deficiency and multiply by 1000.

I don't know, it doesn't seem like dcollections should evoke such a long compile time.

-Steve

Steven Schveighoffer wrote:
> I get a long list of functions proceeding at a reasonable rate.  I've done that in the past, I feel it's some sort of inner loop problem.  Essentially, something takes way longer to compile than it should, but way longer on the order of .05 seconds instead of .005 seconds, so you don't notice it normally.  But somehow my library is able to harness that deficiency and multiply by 1000.
> 
> I don't know, it doesn't seem like dcollections should evoke such a long compile time.

with or without -O ?

On Mon, 23 Aug 2010 13:41:07 -0400, Walter Bright <newshound2@digitalmars.com> wrote:

> Steven Schveighoffer wrote:
>> I get a long list of functions proceeding at a reasonable rate.  I've done that in the past, I feel it's some sort of inner loop problem.  Essentially, something takes way longer to compile than it should, but way longer on the order of .05 seconds instead of .005 seconds, so you don't notice it normally.  But somehow my library is able to harness that deficiency and multiply by 1000.
>>  I don't know, it doesn't seem like dcollections should evoke such a long compile time.
>
> with or without -O ?

The compile line is:

dmd -unittest unit_test.d dcollections/*.d dcollections/model/*.d

Where unit_test.d is a dummy main.

-Steve

Steven Schveighoffer wrote:
> On Mon, 23 Aug 2010 13:41:07 -0400, Walter Bright <newshound2@digitalmars.com> wrote:
> 
>> Steven Schveighoffer wrote:
>>> I get a long list of functions proceeding at a reasonable rate.  I've done that in the past, I feel it's some sort of inner loop problem.  Essentially, something takes way longer to compile than it should, but way longer on the order of .05 seconds instead of .005 seconds, so you don't notice it normally.  But somehow my library is able to harness that deficiency and multiply by 1000.
>>>  I don't know, it doesn't seem like dcollections should evoke such a long compile time.
>>
>> with or without -O ?
> 
> The compile line is:
> 
> dmd -unittest unit_test.d dcollections/*.d dcollections/model/*.d
> 
> Where unit_test.d is a dummy main.

You could try running dmd under a profiler, then.

On Mon, 23 Aug 2010 14:11:52 -0400, Walter Bright <newshound2@digitalmars.com> wrote:

> Steven Schveighoffer wrote:
>> On Mon, 23 Aug 2010 13:41:07 -0400, Walter Bright <newshound2@digitalmars.com> wrote:
>>
>>> Steven Schveighoffer wrote:
>>>> I get a long list of functions proceeding at a reasonable rate.  I've done that in the past, I feel it's some sort of inner loop problem.  Essentially, something takes way longer to compile than it should, but way longer on the order of .05 seconds instead of .005 seconds, so you don't notice it normally.  But somehow my library is able to harness that deficiency and multiply by 1000.
>>>>  I don't know, it doesn't seem like dcollections should evoke such a long compile time.
>>>
>>> with or without -O ?
>>  The compile line is:
>>  dmd -unittest unit_test.d dcollections/*.d dcollections/model/*.d
>>  Where unit_test.d is a dummy main.
>
> You could try running dmd under a profiler, then.

I recompiled dmd 2.047 with -pg added and with the COV options uncommented out (not sure what all is needed)

I then tried running my build script, and it took about 5 minutes for me to give up :)

So I reduced the build line to build just what is necessary to build a hash map.

The compile line looks like this:

dmd -unittest unit_test.d dcollections/HashMap.d dcollections/Hash.d dcollections/Iterators.d dcollections/model/*

I don't think model/* is really needed, but I don't suspect there is too much code in there to compile, it's all interfaces, no unit tests.

So without profiling, the compiler takes 4 seconds to compile this one file with unit tests.

With profiling enabled, gprof outputs this as the top hitters:


Flat profile:

Each sample counts as 0.01 seconds.
  %   cumulative   self              self     total
 time   seconds   seconds    calls  ms/call  ms/call  name
 77.76      6.68     6.68     2952     2.26     2.26  elf_findstr(Outbuffer*, char const*, char const*)
  2.10      6.86     0.18     4342     0.04     0.04  searchfixlist
  1.28      6.97     0.11   663755     0.00     0.00  ScopeDsymbol::search(Loc, Identifier*, int)
  1.05      7.06     0.09  2623497     0.00     0.00  isType(Object*)
  0.76      7.12     0.07   911667     0.00     0.00  match(Object*, Object*, TemplateDeclaration*, Scope*)
  0.76      7.19     0.07   656268     0.00     0.00  _aaGetRvalue(AA*, void*)
  0.58      7.24     0.05  2507041     0.00     0.00  isTuple(Object*)
  0.52      7.29     0.04  2548939     0.00     0.00  isExpression(Object*)
  0.47      7.33     0.04    10124     0.00     0.01  ClassDeclaration::search(Loc, Identifier*, int)
  0.35      7.36     0.03   136688     0.00     0.00  StringTable::search(char const*, unsigned int)
  0.35      7.38     0.03   122998     0.00     0.00  Scope::search(Loc, Identifier*, Dsymbol**)
  0.35      7.42     0.03    79912     0.00     0.00  Parameter::dim(Parameters*)
  0.35      7.45     0.03    43500     0.00     0.00  AliasDeclaration::semantic(Scope*)
  0.35      7.47     0.03    26358     0.00     0.01  TemplateInstance::semantic(Scope*, Expressions*)
  0.29      7.50     0.03  2537875     0.00     0.00  isDsymbol(Object*)
  0.23      7.52     0.02  4974808     0.00     0.00  Tuple::dyncast()
  0.23      7.54     0.02  4843755     0.00     0.00  Type::dyncast()
  0.23      7.56     0.02  1243524     0.00     0.00  operator new(unsigned int)
  0.23      7.58     0.02   904514     0.00     0.00  arrayObjectMatch(Objects*, Objects*, TemplateDeclaration*, Scope*)
  0.23      7.60     0.02   365820     0.00     0.00  speller_test(void*, char const*)
  0.23      7.62     0.02   285816     0.00     0.00  Array::reserve(unsigned int)
  0.23      7.64     0.02   271143     0.00     0.00  calccodsize
  0.23      7.66     0.02   149682     0.00     0.00  Dchar::calcHash(char const*, unsigned int)
  0.23      7.68     0.02    73379     0.00     0.00  TypeBasic::size(Loc)
  0.23      7.70     0.02    39394     0.00     0.00  DsymbolExp::semantic(Scope*)
  0.23      7.72     0.02    20885     0.00     0.00  TemplateInstance::semanticTiargs(Loc, Scope*, Objects*, int)
  0.23      7.74     0.02    11877     0.00     0.00  TemplateDeclaration::deduceFunctionTemplateMatch(Scope*, Loc, Objects*, Expression*, Expressions*, Objects*)
  0.23      7.76     0.02     5442     0.00     0.01  optelem(elem*, int)
  0.23      7.78     0.02                             __i686.get_pc_thunk.bx
  0.12      7.79     0.01  1458990     0.00     0.00  Object::Object()
  0.12      7.80     0.01   656266     0.00     0.00  DsymbolTable::lookup(Identifier*)
  0.12      7.81     0.01   462797     0.00     0.00  Module::search(Loc, Identifier*, int)
  0.12      7.82     0.01   414377     0.00     0.00  Dsymbol::isTemplateInstance()
  0.12      7.83     0.01   354954     0.00     0.00  Expression::Expression(Loc, TOK, int)
  0.12      7.84     0.01   354693     0.00     0.00  Dsymbol::pastMixin()
  0.12      7.85     0.01   167119     0.00     0.00  Dsymbol::checkDeprecated(Loc, Scope*)
  0.12      7.86     0.01   151694     0.00     0.00  Type::merge()
  0.12      7.87     0.01   123694     0.00     0.00  Lstring::toDchars()
  0.12      7.88     0.01   111982     0.00     0.00  el_calloc()
  0.12      7.89     0.01   111569     0.00     0.00  resolveProperties(Scope*, Expression*)
  0.12      7.90     0.01   107359     0.00     0.00  code_calloc
  0.12      7.91     0.01   106932     0.00     0.00  Lexer::peek(Token*)
  0.12      7.92     0.01   106468     0.00     0.00  Scope::pop()
  0.12      7.93     0.01    99136     0.00     0.00  Array::push(void*)
...

I can add more, but I have no idea what part of this is important for diagnosing the problem.  From a naive look, it appears that elf_findstr is the problem (only 3k calls, but uses almost 80% of the runtime?), but I have no idea how to interpret this, and I don't know what the compiler does.

The compiler ended up eventually not producing an exe with the message "cannot find ld", but I don't think the link step is where the problem is anyways.

If you need more data, or want me to run something else, I can.

-Steve

Steven Schveighoffer wrote:
> With profiling enabled, gprof outputs this as the top hitters:
> 
> 
> Flat profile:
> 
> Each sample counts as 0.01 seconds.
>   %   cumulative   self              self     total
>  time   seconds   seconds    calls  ms/call  ms/call  name
>  77.76      6.68     6.68     2952     2.26     2.26  elf_findstr(Outbuffer*, char const*, char const*)
>   2.10      6.86     0.18     4342     0.04     0.04  searchfixlist

elf_findstr definitely looks like a problem area. I can't look at it right now, so can you post this to bugzilla please?

Walter Bright:
> elf_findstr definitely looks like a problem area. I can't look at it right now, so can you post this to bugzilla please?

I am able to find two versions of elf_findstr, one in elfobj.c and one in machobj.c, so it may be possible to remove one of them.

Its docstring doesn't seem to show the 'suffix' argument.

I have seen that it performs strlen() of str and suffix at the beginning, so using fat pointers (C structs that keep ptr + len) as D may be enough to avoid those strelen calls and save some time.

From what I see it seems to perform a linear search inside an Outbuffer, something like a search of strtab~strs inside an array of strings, so the structure may be replaced by an associative set or ordered set lookup instead.

Bye,
bearophile

On Tue, 24 Aug 2010 03:58:57 -0400, Walter Bright <newshound2@digitalmars.com> wrote:

> Steven Schveighoffer wrote:
>> With profiling enabled, gprof outputs this as the top hitters:
>>   Flat profile:
>>  Each sample counts as 0.01 seconds.
>>   %   cumulative   self              self     total
>>  time   seconds   seconds    calls  ms/call  ms/call  name
>>  77.76      6.68     6.68     2952     2.26     2.26  elf_findstr(Outbuffer*, char const*, char const*)
>>   2.10      6.86     0.18     4342     0.04     0.04  searchfixlist
>
> elf_findstr definitely looks like a problem area. I can't look at it right now, so can you post this to bugzilla please?

http://d.puremagic.com/issues/show_bug.cgi?id=4721

-Steve