Strange performance behavior: slow return from controller solved by adding logger:info lines???

[jim rosenblum]

I have a controller that does a few db_find's the last of which returns about 4,000 objects. The method returns JSON

facility('GET', [FacId, Limit], SUser) ->

    Options = case Limit of

 "all" -> [{order_by, recieve_time}, descending];

 _ -> [{order_by, recieve_time}, descending, {limit, to_integer(Limit)}]

end,

    [F] =  boss_db:find(facility, [id, equals, FacId]),

    Reds = boss_db:count(facility,[{status, equals, "red"}]),

    Yellows = boss_db:count(facility,[{status, equals, "yellow"}]),

    P = boss_db:count(facility, [{paused_agents, not_equals, 0}]),

    R = boss_db:find(response, 

    [facility_id, equals, FacId], Options),

    {json, [{facility, F}, {responses, R}, {s_user,SUser},

 {reds, Reds}, {yellows, Yellows},{paused, P}]}.

When the browser makes a request to this endpoint, its responsiveness is slow and variable. Using Chrome's developer tools, I can see that there is a large range from request to First Byte Received - as in 5 seconds to 37 seconds. 80 % of the time it is in the 15 to 25 second range.

But, when I put a logger:info/2 line before and after the last boss_db:find/3, it ALWAYS takes 3 - 4 seconds.... Always...

Anyone have any thoughts