Significant GC performance penalty

[John Colvin]

On Sunday, 16 December 2012 at 07:47:48 UTC, Rob T wrote:
> On Sunday, 16 December 2012 at 05:37:57 UTC, SomeDude wrote:
>>
>> Isn't the memory management completely negligible when 
>> compared to the database access here ?
>
> Here are the details ...
>
> My test run selects and returns 206,085 records with 14 fields 
> per record.
>
> With all dynamic memory allocations disabled that are used to 
> create the data structure containing the returned rows, a run 
> takes 5 seconds. This does not return any data, but it runs 
> exactly through all the records in the same way but returns to 
> a temporary stack allocated value of appropriate type.
>
> If I disable the GC before the run and re-enable it immediately 
> after, it takes 7 seconds. I presume a full 2 seconds are used 
> to disable and re-enable the GC which seems like a lot of time.
>
> With all dynamic memory allocations enabled that are used to 
> create the data structure containing the returned rows, a run 
> takes 28 seconds. In this case, all 206K records are returned 
> in a dynamically generate list.
>
> If I disable the GC before the run and re-enable it immediately 
> after, it takes 11 seconds. Since a full 2 seconds are used to 
> disable and re-enable the GC, then 9 seconds are used, and 
> since 5 seconds are used without memory allocations, the 
> allocations are using 4 seconds, but I'm doing a lot of 
> allocations.
>
> In my case, the structure is dynamically generated by 
> allocating each individual field for each record returned, so 
> there's 206,085 records x 14 fields = 2,885,190 allocations 
> being performed. I can cut the individual allocations down to 
> 206,000 by allocating the full record in one shot, however this 
> is a stress test designed to work D as hard as possible and 
> compare it with an identically stressed C++ version.
>
> Both the D and C++ versions perform identically with the GC 
> disabled and subtracting the 2 seconds from the D version to 
> remove the time used up by enabling and disabling the GC during 
> and after the run.
>
> I wonder why 2 seconds are used to disable and enable the GC? 
> That seems like a very large amount of time. If I select only 
> 5,000 records, the time to disable and enable the GC drops 
> significantly to negligible levels and it takes the same amount 
> of time per run with GC disabled & enabled, or with GC left 
> enabled all the time.
>
> During all tests, I do not run out of free RAM, and at no point 
> does the memory go to swap.
>
> --rt

Use the stopwatch class from std.datetime to get a proper idea of 
where time is being spent. All this subtracting 2 secs business 
stinks.

or just fire up a profiler.