How to find out what's going on

[Michael McDaniel]

On Tue, Jan 03, 2006 at 11:07:56PM +0000, Joel Reymont wrote:
> Folks,
> 
> I'm writing poker bots and my goal is to launch as many per VM as I  
> can. The bots use a binary protocol to talk to the poker server. I'm  
> tracing to a disk log periodically.
> 
> Here I launched 10 bots and looked at the trace log for one of them.  
> I have a separate module that analyzes the disk log.
> 
> 22:52:46: <0.32.0>: Received: 0.000797s: srv_table_state
> 22:53:08: <0.32.0>: Received: 0.000110s: {srv_table_state, ...}
> 
> You can see a difference of 22 seconds above. Normally this would not  
> be cause for concern but the two traces are from two consecutive  
> lines in the same module!
> 
> 	    trace(Bot, 90, "Received: ~.6. fs: ~p",
> 		  [Seconds, Cmd1]),
> 	    trace(Bot, 80, "Received: ~.6. fs: ~p",
> 		  [Seconds, element(1, Cmd1)]);
> 
> Trace itself is defined thusly:
> 
> trace(Bot, Level, Format, Args)
>   when Level =< Bot#bot.debug_level ->
>     {_, Time} = erlang:localtime(),
>     disk_log:alog(Bot#bot.log, {trace, self(), Format, Args, Time});
> 
> How do I find out where the 22 seconds went?
> 
> 	Thanks, Joel
> 
> --
> http://wagerlabs.com/
> 
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^

from disk_log docs ...

"The alog/2 and balog/2 functions asynchronously append an item
 to a disk log."

I'm guessing you are seeing the 22 seconds as that asynchronous 
write.

Also from docs ...
"The log/2 and blog/2 functions synchronously append a term to
 a disk log."


Hmm, asynchronous *item* logging or synchronous *term* logging.
I have not played with it but something to look at.

~Michael