Hook diagnostics

[Buzzkill]

I was reading through some earlier threads around performance of the users.txt file with high counts of players in groups other than "users"  (I too use autopromote in my sandbox server in conjunction with URS to limit access to sweps and ents to specific ranks earned based on time on the server).  While I don't believe I have lag problems around accessing users.txt, I do feel a bit of lag whenever someone spawns in  (which I believe is related more to Patch Protect and its reshuffling of touch rights as people spawn in).

The keyword is "believe".  I have no hard data - just subjective experience.  Enter potentially ridiculous idea #324 into my wee little brain.  If I wanted to try and track true diagnostic timing information around GMod hooks and the processes running within them, would something like this make sense...?

1) Create a high priority hook (-20) for all GMod hooks I'm interested in tracking (ie, PlayerInitialSpawn).  The only logic within each is to record the current high precision time.
2) Create a low priority hook (20) for the same GMod hooks, the logic of which calculates a differential between the current precision time and the previous start time for that particular hook.
3) The delta here should represent the total processing time across all of the various active hooks...  roughly, anyway.

In theory this should start to give me insight into high-intensive processing areas, and I can begin to narrow my investigation/refactoring to the implementations of the hook(s) that show the highest consumption.

Make sense, or am I missing something that might skew the results?  I realize I'm not going to get actual cpu time from any of this  -- but I think it'll give me relative processing requirements and might cast a bright light on hooks that are causing noticeable lag.

Thanks.

[MrPresident]

Whenever someone spawns in, UCL accesses the users.txt file to update it with their name. If you have a large file (hundreds or thousands of users) you will notice small spikes while gmod accesses this file.

[Buzzkill]

Thanks.  My users file is only currently about 40K (file size, not name count). Probably some lag in there that I could tease out with a MySql implementation, but I was curious more about the approach to hook diagnostics and timing data in general.  I'm always interested in knowing if I've introduced lag with a new addon, change in config or general growth.

Thanks. 

[Buzzkill]

My first attempt seems to be working as expected  (shocked, as again, I don't really know lua that well).  This allows "timed hooks" to be created.  In this example, I'm timing PlayerConnects, PlayerInitialSpawn, PlayerSpawn and PlayerDisconnect.  As a sanity check, I have a test case at the bottom that adds a couple artificial timers to PlayerSpawn (simulating lag in a couple different addons).

I still think my object management is ass-backwards.  I don't like having to reference the TimedHook props by the o parm passed in to new(), but for now I'll take "works" over "elegant".

To clarify, this is just me exploring.  I realize my lag spike during PlayerSpawn is likely due to file access against a larger-than-normal users.txt, but I'm more interested in exploring under the hood of ULib and lua than solving a small lag problem at the moment. 

/garrysmod/addons/diagnostics/lua/ulib/modules/server/hooker.lua

Code: Lua

1. HookDiag = {}
2. HookDiag.TimedHook = {}
3. HookDiag.TimedHooks = {} -- really just a convenience container.
4.  
5. function HookDiag.TimedHook:new (o)
6.         o = o or {}
7.         setmetatable(o, self)
8.         self.__index = self
9.          
10.         o.Time_Delta = 0
11.         o.Time_Start = 0
12.          
13.         hook.Add( o.HookName, o.HookName.."_diag_hi", function()
14.                 o.Time_Start = SysTime()
15.         end, -20)
16.        
17.         hook.Add( o.HookName, o.HookName.."_diag_lo", function()
18.                 o.Time_Delta = SysTime() - o.Time_Start
19.                 print("[HOOKDIAG] "..o.HookName, o.Time_Delta)
20.         end, 20)
21.        
22.         return o
23. end
24.  
25. function HookDiag.TimedHooks:Create(hookname)
26.  
27.         local timedhook = HookDiag.TimedHook:new{ HookName = hookname }
28.         table.insert( HookDiag.TimedHooks, timedhook )
29.         print("[HOOKDIAG] Created timed hook for "..hookname)
30. end
31.  
32.  
33. HookDiag.TimedHooks:Create("PlayerConnect")
34. HookDiag.TimedHooks:Create("PlayerInitialSpawn")
35. HookDiag.TimedHooks:Create("PlayerSpawn")
36. HookDiag.TimedHooks:Create("PlayerDisconnected")
37.  
38.  
39.  
40. ---- test case  -- creates an artifical pause to validate timing.  ----
41.  
42. local function uglyPause(secs)
43.         local t1 = os.time()
44.         print ("Pausing for ", secs, " seconds")
45.         while (os.difftime( os.time(), t1) < secs) do
46.         end
47. end
48.  
49. hook.Add( "PlayerSpawn", "testcase1a", function()
50.                 uglyPause(3)
51. end)
52.  
53. hook.Add( "PlayerSpawn", "testcase1b", function()
54.                 uglyPause(7)
55. end)
56.  

Output....

Code: [Select]

....
[ULIB] Loading SERVER module: hooker.lua
[HOOKDIAG] Created timed hook for PlayerConnect
[HOOKDIAG] Created timed hook for PlayerInitialSpawn
[HOOKDIAG] Created timed hook for PlayerSpawn
[HOOKDIAG] Created timed hook for PlayerDisconnected
....
[HOOKDIAG] PlayerInitialSpawn   0.041178760999856
Pausing for     3        seconds
Pausing for     7        seconds
[HOOKDIAG] PlayerSpawn  9.906730554


[Stickly Man!]

That is definitely interesting stuff! I'm glad you like poking under the hook too- you're likely to come across something that we've missed

Some thoughts:
If you are using the latest SVN of ULX/ULib, we've changed hook priority to be a set of constants, so you'd want to use HOOK_MONITOR_HIGH and HOOK_MONITOR_LOW for better results.   (Also, we're petitioning to get this hook library implemented in Garry's Mod by default... hopefully)

Also, why not just temporarily modify our hook.lua (around 97), check if the hook name matches what you want to test, then do the measurement from there? You should get similar results, but at least this way you're absolutely sure that it's measuring all of the hook (since a similar high priority one might get called before your measurement hook).

And one other related note: There is "DBugR" by oubliette that has some pretty powerful tools for performance and testing. It's pretty rough around the edges and should definitely not be used permanently, but it's fun to play with, and may give you some useful information:
http://facepunch.com/showthread.php?t=1360275

[Buzzkill]

Thanks.  Not looking for bugs in ULib per se, but measurements are 80% of the battle.  I have no idea if I'm running at peak performance or wasting cycles in a horribly coded addon if I don't measure.

I went to hook.lua first, actually.  I could get lots of info from there, including timing on specific functions attached to the hooks. I noticed I can't do brute force debug messages (ie, 'print', which is nil inside hook.lua). Is the env within hook.lua non-global?

I was also thinking if this had any wheels that wrapping it up as an addon would be problematic if I were attaching directly to core code.

OMG... drooling as I look at DBugR.  Thanks.  Will go play with that now..  because...  you know...   it's Tuesday at 1:55 and I should be working, but this is more fun. 

[Buzzkill]

  Installed.  This makes my work with blind hook timers look pathetic.

[Stickly Man!]

Yeah, I can't remember the specifics as to why, but any things you need to use in the hook.lua file must be declared as local at the top of the file. Print is already listed there, but commented out. Uncomment them and you should be able to print just fine.
https://github.com/Nayruden/Ulysses/blob/master/ulib/lua/ulib/shared/hook.lua#L12-L13

Haha, let me know if you fully figure out DbugR- I played around with it for a while once, but not long enough to figure out all it could do. Oh, crap, work. I should be doing that now! *closes forums*

Edit: But hey! Doing them manually with timers helps you understand and appreciate how it all works!

[Aaron113]

Yeah, I can't remember the specifics as to why, but any things you need to use in the hook.lua file must be declared as local at the top of the file.

That's because it's a module.  I couldn't tell you as to why exactly it is that way, but the brief explanation.  It's kind of like python or c++ I suppose, where you have to import the libraries you want to use so it doesn't have a bunch of useless functions that it never runs.  I don't entirely understand the logic behind it with GLua, but yeah.

And DBugR looks pretty amazing, that would've been useful to have a few years ago.

[Buzzkill]

The data coming from this thing is amazing.  Already identified some rather poor coding choices in some of my addons  (iterating through every spawned entity in a Think() just to find one in particular?  Really??  )

Do we know what the unit of measure is for the Value column in Pinpointing?  I looked through the FP threads and couldn't find anything concrete.  Haven't cracked open the code yet, but will if no one knows off the top of their heads.  I'm assuming it's a relative measure (eye, ostime between call and return, like I was doing above), but that's just an assumption.

Thanks again.

Edit: But hey! Doing them manually with timers helps you understand and appreciate how it all works!

Agree 100%. 

[Stickly Man!]

Glad it's working well for you!

I'm not quite sure- just by looking at the screenshots, value is likely the total amount of time said hook/function has taken to run in total- since the start of the server probably. (Does the total only go up? Or does it go up and down?) It's been a while since I last played with DBugR, so I'll have to dig it up again when I get the chance.

[Buzzkill]

It stays fairly constant, so I think it may be some total (of something) per second. since the column next to it is showing function entries per second.  I'm unclear what that "something" is.  Could be cpu time if it was calculating across multiple threads, but that doesn't make much sense in this context.   I'll just call it "work". 

[rNd]

I'd really hate to bump an old thread but I've can't for the life of me figure out how to get Dbugr to work. I've tried messing with the settings and I have reread the dev's instructions several times but the command  'dbugr_menu_open' never works. Perhaps it is broken or maybe there is something that I'm failing to do that that you guys managed to do here?

[Buzzkill]

Is it registering properly?  One clue would be if autocomplete gives you the dbugr commands as you begin to type.  Of course, the other clue would be console logs from the server. 

[Stickly Man!]

*Large Bump*

FPtje just released a new profiler tool (FProfiler) that's worth taking a look at:
https://facepunch.com/showthread.php?t=1517058