I think the best way to report this issue is just to post the log from the chat on the newbie channel. It seems like this kind of lag is pretty commonly experienced, which makes me think it's server side. If it is, can anything be done about it? If it's not, can someone offer some suggestions on what might be causing it and what can be done?



Kiurthax: I'm experiencing odd slowdowns with my connection to the mud on otherwise lagless commands every so often. Is this specific to my connection or is it mudwide lag?

A helpful mortal: I am had no lag here

Prug: no log.

Prug: lag that is.

Talis: I think I've noticed it; sometimes when I look it takes a second or two to get a response.

Kiurthax: In that case, does anyone know why I would experience that kind of lag here but not on other muds? Could it be traffic specific to port 9999? Would forwarding that port help at all?

An Immortal: You can run a trace rout to figure out if the issue is indeed you. If you are not familiar with it and using a Widows based OS you can do a help search on tracert

Kiurthax: It's constant - if I type "score" 25 times in a row quickly, invariably on the seventh or eighth I will get about four seconds of stop-time where nothing happens, then I get a ton of stuff all at once.

Kiurthax: I'm somewhat familiar with tracert. Do I just run it against google.com or whatever, and send the traffic through 9999?

An Immortal: Background programs can also effect it, like virus scanners and fire-walls.

An Immortal: I would run it to the MUDs IP.

A helpful mortal: It's not him, it's the mud. I have the same problem with periodic lag, every ~8 steps down the road for instance.

A helpful mortal: It's very annoying and a constant problem

Kiurthax: Okay, I will give that a shot. Thank you.

Kiurthax: I'm not sure if it's the mud or not. The other muds that I don't experience this problem on are not running on port 9999 so it's hard to be sure.

A helpful mortal: An immortal told me once that CF runs a logger in the background to fix bugs/crashes, and that IT causes lag

Kiurthax: All I know is that I would like to figure out/fix the issue before I play a serious character again, because it's rather hard to PK or survive PK in those kinds of circumstances :P

A helpful mortal: I just wish they'd stop doing it

A helpful mortal: I doubt that the situation is going to resolve itself to your satisfaction, friend, unfortunately. It's been going on for months and all of my complaining hasn't changed it.

An Immortal: I don't experience any lag usually unless it is from my side (or my ISP). I would check into factors other then the MUD or port, unless you are using the same port for other programs as well.

Kiurthax: Well, I'm still going to try the tracert thing just to try to see if it's on my end. I have a friend who plays this game who told me that she's not experiencing the stuff that I've been complaining to her about.

An Immortal: If all else fails, make a post. Some tech savy people can assist you in finding the issue and resolving it.

A helpful mortal: Lot of computer nerds here.

Kiurthax: I'm fairly certain it's not my ISP, since I don't experience the issue on other muds at all. It has to either be the mud's server or something funky happening to port 9999 at some point along the line.

Kiurthax: I'm not 100% sure how this traceroute result is going to help me, though. I see twelve hops, and the longest ones are at theplanet.com which I'm guessing is CF's host.

A helpful mortal: the first one is you, last one is the server

Kiurthax: Still, none of them are above 150 ms, which doesn't seem to indicate any problem. Then again, the lag is somewhat intermittent, so I might need to run several traceroutes I guess.

A helpful mortal: Yeah, the lag I always have is periodic, fine fine fine fine fine hang for 2 seconds, fine fine fine fine fine fine fine fine hang for 2 seconds, fine fine fine fine

A helpful mortal: It might very well be your computer.


Kiurthax: That's exactly what I'm talking about, the hanging for 2 seconds thing. Exact same thing.

Kiurthax: Is that something that only the two of us are experiencing, or is it mudwide? That would go a long way to explaining whether it's on our machines or not.

Talis: Yeah, I'm experiencing that problem too.

Kiurthax: I know that I've seen this same thing for several days now, so if it is my machine, it's something that is always affecting it.

A helpful mortal: Happens to me on multiple machines

A helpful mortal: From different places

I keep thinking I'm lagging when I put in a number of directions, but it's just that all of the commands are caught up a lot quicker than what I'm used to so I end up just standing there with the mud waiting for my next input... THANKS GUYS!!!!!

So I know which function it's happening in, and it is the one I suspected since this does the majority of the processing. It's also an enormous function, and it'll take me some time to walk through and see if there is anything in there we're doing stupid.

Just letting you know I am actually looking into this.

nt

Now I just need to figure out a better way to accomplish what it's doing.

n/t

So was it something added fairly recently, or something that's been in effect for a while?

n/t

Essentially:

At some point hardware just outpaced the hell out of the processing the MUD requires, and we got, if not lazy, less vigilant about performance in some things. Making sure that things ran correctly became a lot more important than making sure they also could run efficiently. Eventually, it added up in one area and started to bite us in the ass.

I cleaned up a little bit of it yesterday; Zulg cleaned up a lot of it and added better tracking so we can get it down even a bit further.

Out of curiosity, what kind of lag do people see at the tick? A lot of the processing that happens then pretty much has to, but I can think of a few things that can be cleaned up bit there, too performance-wise -- and if necessary I can make that more of a priority.

As an end user it's hard to get exact numbers for tick lag since I can't know when the tick is about to happen. Have to just poll as quickly as possible then check the delta between "last poll prior to tick" and "first poll after tick".

Using that method it doesn't appear there's any special lag at the tick. My median round-trip when not spanning a tick is approx. 250 ms. My ping is 20 ms, so approximately 2/3 of that 250 ms is spent on the server instead of on the wire. For tick-spanning round-trips the median is approx. 300 ms.

That said, I still get a few round-trips that are substantially longer than others. They're just not 2500-3000 ms like before. Now the longest ones are approx. 900 ms, though I did see one or two that were 1700 ms. The 1700 ms ones aren't nearly as common as the 900 ms variety.

>That said, I still get a few round-trips that are
>substantially longer than others. They're just not 2500-3000
>ms like before. Now the longest ones are approx. 900 ms,
>though I did see one or two that were 1700 ms. The 1700 ms
>ones aren't nearly as common as the 900 ms variety.

Yup, and the perf tracking I added has pointed to a few other issues with little spikes like that, but happen way less often than the ones I've fixed. There is a class of these that I'm looking to to wrap into a single function since they all walk the same list and do something when it finds a specific item or ten in that list. So I should be able to knock out another chunk of them next time I get some sit-down code time.

Would you mind bumping this thread if/when you eventually do some more refactoring?

So we as players receive the lag a lot less often?

Obviously I'm just wishful thinking that that's even possible.

Also, you kick ass for looking at this. =)

So this function takes 1.06 seconds to execute today.

It of course calls all sorts of other functions, and the biggest culprit of those takes 0.84 seconds to execute.

Within that function are two sections of code:
Section 1 takes 0.23 seconds (This is what was added 6 months ago)
Section 2 takes 0.60 seconds (This is what's been there for 4 years)

I've removed the code for Section 1 which was really a hack anyway, and created a proper way to accomplish that which has zero consistent impact on the game.

Now to figure out how to refactor section 2.

>Section 2 takes 0.60 seconds (This is what's been there for 4
>years)
>
>Now to figure out how to refactor section 2.

Done...and I've also make this take less than 0.01 seconds, so it too is negligible in the grand scheme. Along with this I've added some performance data tracking for certain progs (which is where we are seeing these spikes), so we can start working on the handful of others that take between 0.01 & 0.20 seconds.

Overall you should definitely notice a difference as of the reboot I'm in the process of right now.

And well explained for those of us who are not IT gurus!

whether it is just me that can't log back on.

That's part of the fix.

n/t

A mud pulse is about 0.2s (am I correct?), thus, ideally, we would want to complete all calculations in 0.1s.
Does that mean that 0.01s is still high, considering we may have several functions like this?

>A mud pulse is about 0.2s (am I correct?), thus, ideally, we
>would want to complete all calculations in 0.1s.

No clue...

>Does that mean that 0.01s is still high, considering we may
>have several functions like this?

That's why the performance tracking things I've added check the larger functions (like mobile_update() which typically takes between 0.03 & 0.05 seconds now, not the 1.06 seconds it was), along with a few special cases further down in functions that have been problematic in the past.

It should be easy to narrow down issues like this now, and prevent them from hanging around for 4 years.

>>A mud pulse is about 0.2s (am I correct?), thus, ideally,
>we
>>would want to complete all calculations in 0.1s.
>
>No clue...

In ROM 2.4 code we have:


#define PULSE_PER_SECOND 4
#define PULSE_VIOLENCE ( 3 * PULSE_PER_SECOND)
#define PULSE_MOBILE ( 4 * PULSE_PER_SECOND)
#define PULSE_MUSIC ( 6 * PULSE_PER_SECOND)
#define PULSE_TICK (60 * PULSE_PER_SECOND)
#define PULSE_AREA (120 * PULSE_PER_SECOND)


So: 1 pulse = 1/4 = 0.25s.
It actually makes sense because PULSE serves as minimal "atomic" operation time (at which player's commands can be processed) and average human reaction time is about 0.2s. As we grow older our reflexes start to suck, so 0.25s is fine }(

I'm not sure if it's still the case in CF, but given that a pulse is about 0.25, we want to complete all commands and return the result to a player within those 0.25s (or even in 0.1-0.15 to mitigate lag or other possible server issues like swapping or cache misses). Things like mobiles can be updated less frequently, but for the sake of smoothness it is really cool to have all these updates (mobiles, ticks, combat rounds, etc) to fit a pulse, so we will not hang every tick or every combat round.

I swear my physical reflexes and my mental reaction time (mental reflexes...err....daaaaawwww?) are better than just about everyone I know, with a couple exceptions (both are twitch-gamers too). I'm curious if that is a real or a perceived benefit of the cyber age.

Wiki: Reaction time

It has always frozen for a second or so at the tick.. But now it's much worse (and I checked my ping in parallel, no connection problems). Pulse lags every few seconds.

I'll try to take a look at this this weekend.

Divorce here I come? ;)

Your lives seem so strange from over here in bizarro world, where my wife tries to get me to MUD more.

n/t

.

.

It's part of my dubious charm!

> A helpful mortal: Yeah, the lag I always have is
>periodic, fine fine fine fine fine hang for 2 seconds, fine
>fine fine fine fine fine fine fine hang for 2 seconds, fine
>fine fine fine

And tracert shows no problems with the last hop being around 160ms.

Nobody has reported any bad pings during the period where they've seen this lag behavior. So "general network congestion" doesn't really work as an explanation. My home connection is also pretty ridiculously good, and I still see the in-game lag.

I suppose it's possible there's some sort of "traffic shaping" going on somewhere along the line, but then again I see the behavior both from work (private hosting company) and from home (SBC DSL).

For kicks, I downloaded this TCP-based ping utility that does the same thing except using TCP SYN packets instead of ICMP. For the most part the performance looked about the same, but I did get one round-trip that was around 3000 ms. I didn't see any like that using the normal ICMP-based ping.

Can download it here if you want to try:

http://www.elifulkerson.com/projects/tcping.php

Can also use it to "ping" websites (tcp port 80) that block normal ICMP traffic (e.g. www.ibm.com).

I doubt its server side.

If I get some free time I'll write up a tintin++ script to just enter a command in a loop and see how long it takes to get the response. Sort of like ping, but not using ICMP, and talking to the cf code.

I'll let that run for 10 minutes and let you know what I see.

Here you go. This is for yTin:

#ali {go} {#ali {send} {worth;#math {elapsed} {$_msec}};#ali {recv} {#math {elapsed} {$_msec - $elapsed};#showme {elapsed: $elapsed}};#ali {off} {#unvar {elapsed};#unali {send};#unali {recv};#unali {off};#unact {which is worth}};#act {which is worth} {recv;send};send}

Connecting from work, I see the same occasional lag spikes as you. A given spike results in a 2000-3000 ms round trip, up from a median round trip of approx. 250 ms.

The spikes occur every 6 seconds with extreme consistency.

Hey IMP guys: is there some long running task the mud undertakes every 6 seconds? Possibly writing to disk?

.

I get the same thing, though I think my lag might be worse than 6 seconds.

Its the reason I don't play melee classes (on the rare occasion that I even play) anymore.

The lag isn't six seconds, that's just how often it occurs.

So I get some number of 250 ms round trips, followed by a 2000 ms round trip. The 2000 ms round trips happen around every 6 seconds.

Just re-ran the test from home and got the same results.

On a whim, I thought maybe the long round-trips were due to the fact that I was spamming commands. So I put 3 second delays between each "worth" command. Didn't make a difference.

I brought this to Valg's attention long ago (might even be on the BB), but when I was in Scion I noticed that every time my nightwalker gated to me I'd get a brief lag spike. Every. Single. Time. He said it was nothing, iirc. But that can't be right.

Please please please please please can we fix this?

Happens to me from multiple ISPs, DSL and T1 connections, from a Mac and a PC. It's definitely something that's MUD side, and it's getting to the point where it affects my enjoyment and desire to play at all. It'd be pretty ghey if I stopped playing after 10 years because something that could possibly be resolved isn't.


Zen


PS You are the man for figuring this out.

It's thrown off my timing on walking sometimes, especially when fleeing from other people. It doesn't get me killed often yet but it will eventually.

It needs to be fixed.

I did a simple test. Logged in and kept typing enter:

More in the next post but let this sink in first.

civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>


civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>

civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>

civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>



civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>

civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>























civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>

civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>


civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>
civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>

civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>


civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>

civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>


civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>

civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>

civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>


civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>


civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>


civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>



civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>

civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>

civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>




















civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>
civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>



civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>

civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>

civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>


civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>

civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>


civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>

civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>


civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>

civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>


civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>

civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>


civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>

civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>



















civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>

civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>

civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>

civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>

civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>



civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>

civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>


civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>


civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>

civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>


civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>

civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>


civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>

civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>


civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>
The Theran form of SOMEGUY appears before you.

civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>












civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>

civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>

civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>

civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>

civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>


civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>

civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>


civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>

civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>

civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>


civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>

civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>


civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>


civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>

civilized <100%hp 100%m 100%mv 2000tnl (50.00%)>

*** Edit: I performed variants of this for the course of about twenty minutes, using different commands from a couple different IP sources (yay neighbors' wirelesses) with VERY similar results ***

I also pinged the hell out of port 9999 without any lag whatsoever...

Zulg (or whoever?): Is there some sort of CPU-intensive crunch that is occurring every certain interval somewhere?

Maybe even a usleep in some controller thread somewhere? It seems pretty consistent.

grep the source on "sleep" =)

Good luck!

I think solving this will make us all happycampers =)

Evar.

>> Hey IMP guys: is there some long running task the mud undertakes every 6 seconds? Possibly writing to disk?

That would be Iunna deleting a pfile I think :)