This forum is a read-only archive of the Gammon Software forum (2000–2026). No new posts can be made. Search the archive.

Adding tenths and hundreths of a second to logging

Posted by Batista on Sat 31 Dec 2005 12:03 PM — 9 posts, 32,184 views.

Batista #0
The logging features of MUSHclient are amazing already. Logging in seconds helps a lot with timing my attacks, balances, and whatever else. However, sometimes I need to test the speed of weapons, and that means I have to check the miliseconds.

Is it possible to add this feature into MUSH? Or is it in already and I don't know? I checked Flannel's script on this thing, but it's not very practical. I'd like to be able to log in my spars and duels. Having my triggers disabled isn't fun.

I was thinking maybe have a logging flag thingy that'll let you display time like: HRS:MINS:SEC.TIMEtoTWOorTHREEplaces.

Just a small suggestion. Other than that, the logging is absolute perfection.

Nick Gammon Australia Forum Administrator #1
I'm not totally sure how practical that is, with network lag at, say, 0.5 seconds, you may find a millisecond timer would confuse you with inaccurate readings.

The trouble is, it isn't that easy to do. Most of the timers in Windows are to a second granularity, and thus the date/time formatting used in the logging only offers seconds. In fact that is a call to a "library" function which I didn't write. If I changed that I would have to do quite a bit of extra code.

What you could do it do your own logging, and in the script use GetInfo (232) to find the high-performance timer figure, which is a floating-point number that should be very accurate. However you then need to convert that into a date/time.
Tsunami USA #2
Without looking at the documentation or anything, I'm assuming GetInfo(232) returns the timestamp? Simple subtraction should suffice then, since its really only the difference in time I ever require, not the actual time.
Batista #3
Hmm... how do I interpret this, exactly? If you can tell me that, I think I could probably figure out how to play around with it.

By the way, thanks for pointing that out to me!
Nick Gammon Australia Forum Administrator #4
Interpret? Well, if you make a trigger that matches everything (eg. match on *) and "send to script", then you could write to the log file with your own preamble. You could use GetInfo (232) to find the number of seconds in the timer, and subtract each line from the previous line to get the difference.
Batista #5
Ok, so I should:

1.) Make a trigger to match on everything.
2.) Have it 'send to script'.

I'm confused what to do next. I am right now using the WriteLog function to send GetInfo(232) to script. However... my logs then read like a tax report.

I'd like to be able to have each line read something like:

[23.455] You slash into newbie.
[26.675] You have recovered balance.

Right now it reads more like:

3434h, 4343m -
6543420.43434341455
You slash into newbie.
6543423.23242342423
3434h, 4343m -
6543425.43532352542
You have recovered balance.
6543430.63237678346

I'm probably going to smack myself in the head and scream, "That was so simple!" after I make this post, but...

Any idea how to make this happen? Is there some way to put the value of GetInfo(232) into a preamble option for output in the logging options section?

Sorry for all the questions, but it's just one of the few things I've not been able to figure out on my own.
Batista #6
Oh, and by 'interpret' I mean what the number in GetInfo(232) stands for and where it comes from.
Nick Gammon Australia Forum Administrator #7
Quote:

However... my logs then read like a tax report.


Lol.

The info returned from GetInfo (232) is the internal timer, in seconds as a floating point number. It doesn't refer to any particular time. What you really want is the difference between each line. This trigger (written for Lua, but other languages would be similar) does that:


<triggers>
  <trigger
   enabled="y"
   keep_evaluating="y"
   match="^(.*)$"
   regexp="y"
   send_to="12"
   sequence="90"
  >
  <send>
if not previousTime then
  previousTime = GetInfo(232)
end -- first time through

-- time since last line
diff = GetInfo(232) - previousTime 

WriteLog (string.format ("[%.3f] ", diff), "%1")
</send>
  </trigger>
</triggers>


First time through, previousTime will be nil, so we set it to the current timer. That makes each subsequent line offset from when we starte logging. That cuts out the really big numbers before the decimal point.

Then we use %.3f in string.format to cut down the precision to only 3 decimal places. This gets rid of a lot more digits.

Then we use a single WriteLog to avoid the extra newline.

I gave it a sequence number of 90 to put it ahead of other triggers, and "keep evaluating" so other triggers would still be done. I also turned off "log output" in the general logging, as this trigger is doing it instead.

This is the sort of result I get:


[449.819] <1000hp 1000m 1000mv> 
[449.825] Vertic Avenue
[449.825] Nothing in particular strikes your attention as you walk down this portion
[449.825] of Vertic Avenue.  It seems almost as if the citizens of the city forgot
[449.825] to place a statue here, or perhaps a plaque.  The lengthy road ranges
[449.825] to the north and south.
[449.825] Exits: north south.
[449.825] 
[452.793] <1000hp 1000m 1000mv> 
[452.825] You are carrying:
[452.825]      Nothing.
[452.825]


These numbers are actually cumulative time since the start of logging.
Amended on Tue 03 Jan 2006 04:48 AM by Nick Gammon
Nick Gammon Australia Forum Administrator #8
Or, if you just want the difference between each line, use this version:


<triggers>
  <trigger
   enabled="y"
   keep_evaluating="y"
   match="^(.*)$"
   regexp="y"
   send_to="12"
   sequence="90"
  >
  <send>
if not previousTime then
  previousTime = GetInfo(232)
end -- first time through

-- time since last line
diff = GetInfo(232) - previousTime 

WriteLog (string.format ("[%.3f] ", diff), "%1")

-- save for next time
previousTime = GetInfo(232)
</send>
  </trigger>
</triggers>


This gives:


[0.032] Vertic Avenue
[0.000] Nothing in particular strikes your attention as you walk down this portion
[0.000] of Vertic Avenue.  It seems almost as if the citizens of the city forgot
[0.000] to place a statue here, or perhaps a plaque.  The lengthy road ranges
[0.000] to the north and south.
[0.000] Exits: north south.
[0.000] 
[1.892] <1000hp 1000m 1000mv> 
[0.107] You are carrying:
[0.000]      Nothing.
[0.000]