Register forum user name Search FAQ

Gammon Forum

Notice: Any messages purporting to come from this site telling you that your password has expired, or that you need to verify your details, confirm your email, resolve issues, making threats, or asking for money, are spam. We do not email users with any such messages. If you have lost your password you can obtain a new one by using the password reset link.

Due to spam on this forum, all posts now need moderator approval.

 Entire forum ➜ MUSHclient ➜ Bug reports ➜ Inexplicable delay after sending a command. (Second-hand explanation)
Inexplicable delay after sending a command. (Second-hand explanation)

It is now over 60 days since the last post. This thread is closed.     Refresh page

Pages: 1  2 3  

Posted by Twisol   USA  (2,257 posts)  Bio
Date Reply #15 on Tue 15 Dec 2009 10:03 AM (UTC)
Message
Or pastebin. Pastebin would be nice. >_>
'Soludra' on Achaea

Blog: http://jonathan.com/
GitHub: http://github.com/Twisol
Top
Posted by Kayle   (5 posts)  Bio
Date Reply #16 on Tue 15 Dec 2009 10:54 AM (UTC)
Message
http://pastebin.com/f5480d488


There's two different ones. The first one is the one I was using to test the lag. The second was the one I used a couple weeks ago while testing the output of changes to my MUD. Both displayed the lag issues, but I figured something might be different between them.
Top
Posted by Nick Gammon   Australia  (23,133 posts)  Bio   Forum Administrator
Date Reply #17 on Tue 15 Dec 2009 07:51 PM (UTC)

Amended on Tue 15 Dec 2009 09:49 PM (UTC) by Nick Gammon

Message
Still seems fast to me on my PC. Let's try to time it. Internally the processing is similar for a scripted send, compared to typing something in.

Please press Ctrl+I to open the Immediate window, and then paste in this:


tstart = os.time ()

for i = 1, 20 do
  Send ("look")
  Send ("score")
end -- for

tend = os.time ()
print ("Time taken =", os.difftime (tend , tstart))


You could change "look" and "score" to something else that works on your MUD, but these probably will. I am sending two different commands to avoid the MUD disconnecting us because of spamming the same command.

Then hit the "Run" button, and then close the window and check the output window.

What the client does here is process the command, echo it on the screen, and send it to the MUD. Because of the asynchronous nature of MUD processing you see all commands echoed before any are replied to. However the claimed problem here is not the MUD response time, but the time taken to echo the command locally.

When I run that (on my local MUD server) I see this:


look
score
look
score
look
score
look
score
look
score
look
score
look
score
look
score
look
score
look
score
look
score
look
score
look
score
look
score
look
score
look
score
look
score
look
score
look
score
look
score
Time taken = 0
Inside the Northern Gate
You stand inside the northern gate of Darkhaven.  To the south lies the
intersection of Vertic Avenue and Justice Road.
Exits: north south.
A gate guard tends the north gate.

<24hp 145m 110mv> <#21100> 
Score for Admin the Attendant.

... and so on


The important thing here is that the time taken to execute 40 commands (20 x 2) is under 1 second. Now maybe the delay is in between when you hit <enter> and when command processing even starts, but we may as well rule out the obvious.

A minor change gives higher granularity results:


tstart = GetInfo (232)  -- high performance timer

for i = 1, 20 do
  Send ("look")
  Send ("score")
end -- for

tend = GetInfo (232)
print ("Time taken =", tend - tstart)


In this case I got:


Time taken = 0.067820332478732


So you can see I processed 40 commands in 68 milliseconds, that is about 1.4 milliseconds per command, far faster than the reported 250 milliseconds per command.

This is on Windows XP SP3
Intel Core 2 Duo CPU at 3.06 GHz
512 Mb of RAM

(running under VMware - the host processor has 4 Gb RAM)



Another test can show how long it takes for everything to be processed, including receiving responses. We need an alias and trigger for this:


<aliases>
  <alias
   match="start"
   enabled="y"
   send_to="12"
   sequence="100"
  >
  <send>

tstart = GetInfo (232)  -- high performance timer

for i = 1, 20 do
  Send ("look")
  Send ("score")
end -- for

Send ("say End timing test.")

tend = GetInfo (232)
print ("Time taken to send =", tend - tstart)

</send>
  </alias>
</aliases>

<triggers>
  <trigger
   enabled="y"
   match="*You say 'End timing test.'"
   send_to="12"
   sequence="100"
  >
  <send>

outputend = GetInfo (232)
print ("Time to receive all output =", outputend - tstart)

</send>
  </trigger>
</triggers>


Template:pasting For advice on how to copy the above, and paste it into MUSHclient, please see Pasting XML.


The alias (type "start") starts the high-performance timer, and the trigger notices when the final "say" arrives, indicating all commands have been processed.

In my case I got this:


look
score
look
score
look
score
look
score
look
score
look
score
look
score
look
score
look
score
look
score
look
score
look
score
look
score
look
score
look
score
look
score
look
score
look
score
look
score
look
score
say End timing test.
Time taken to send = 0.0024757329374552
Inside the Northern Gate
You stand inside the northern gate of Darkhaven.  To the south lies the
intersection of Vertic Avenue and Justice Road.
Exits: south.
A gate guard tends the north gate.

... (about 650 lines here) ...

<24hp 145m 110mv> <#21100> You say 'End timing test.'
Time to receive all output = 10.213389072102


In this case it sent all 40 commands in 2 milliseconds. Now it took over 10 seconds to get everything back (over 600 lines) but I think here, the MUD has "throttled" command processing (which is perfectly reasonable for it to do) because I saw slight pauses between each lot of output arriving back.
- Nick Gammon

www.gammon.com.au, www.mushclient.com
Top
Posted by Zeno   USA  (2,871 posts)  Bio
Date Reply #18 on Tue 15 Dec 2009 08:27 PM (UTC)

Amended on Tue 15 Dec 2009 08:34 PM (UTC) by Zeno

Message
Using:
tstart = GetInfo (232)  -- high performance timer

for i = 1, 20 do
  Send ("look")
  Send ("score")
end -- for

tend = GetInfo (232)
print ("Time taken =", tend - tstart)


Quote:
look
score
look
score
look
score
look
score
look
score
look
score
look
score
look
score
look
score
look
score
look
score
look
score
look
score
look
score
look
score
look
score
look
score
look
score
look
score
look
score
Time taken = 0.64238667204336
Floating in a void
Exits: none.

That's more or less a massive difference between what you got.

MUSHclient 4.15, new unsaved world
WinXP SP3, 2.52 GHz, 1GB RAM

[EDIT]
Time taken = 0.076577051004278
Same machine, upgraded MC to 4.43
Zeno McDohl,
Owner of Bleached InuYasha Galaxy
http://www.biyg.org
Top
Posted by Nick Gammon   Australia  (23,133 posts)  Bio   Forum Administrator
Date Reply #19 on Tue 15 Dec 2009 08:37 PM (UTC)
Message
OK, tried another PC.


Time taken = 0.009738667903548


This one using MC 4.44.
Windows XP SP3 2.93 GHz Pentium
2 Gb RAM

- Nick Gammon

www.gammon.com.au, www.mushclient.com
Top
Posted by Nick Gammon   Australia  (23,133 posts)  Bio   Forum Administrator
Date Reply #20 on Tue 15 Dec 2009 08:49 PM (UTC)
Message
Now on my old PC I don't use much any more:


Time taken = 0.0068177596444059


This is using MUSHclient 4.24.

Windows NT 4
2.4 GHz Pentium 4
512 Mb RAM

That's still under 7 ms to process 40 commands. :)
- Nick Gammon

www.gammon.com.au, www.mushclient.com
Top
Posted by Nick Gammon   Australia  (23,133 posts)  Bio   Forum Administrator
Date Reply #21 on Tue 15 Dec 2009 08:52 PM (UTC)
Message
Yet another PC (how many do I have?) ...


Time taken = 0.014709955469073


This one is Windows XP SP2
3.00 GHz Pentium 2, with 2 Gb RAM

MUSHclient 4.42
- Nick Gammon

www.gammon.com.au, www.mushclient.com
Top
Posted by Nick Gammon   Australia  (23,133 posts)  Bio   Forum Administrator
Date Reply #22 on Tue 15 Dec 2009 08:55 PM (UTC)
Message
Running on Ubuntu (under VMware, on a iMac):

MUSHclient 4.40


Time taken = 0.030904757195465


iMac 3.06 GHz Intel Core 2 Duo
4 Gb RAM

(Same as test earlier up this page, was running Windows XP under VMware on the iMac).

- Nick Gammon

www.gammon.com.au, www.mushclient.com
Top
Posted by Nick Gammon   Australia  (23,133 posts)  Bio   Forum Administrator
Date Reply #23 on Tue 15 Dec 2009 09:03 PM (UTC)
Message
I am still interested in hearing from Kayle about what happens with packet debug turned on. It is possible the command is processed quickly, but simply not drawn quickly (the packet debug should therefore show the command being sent before the screen redraw).

Or, is the delay such that it is sent (in packet debug) and drawn in the output window at about the same moment?
- Nick Gammon

www.gammon.com.au, www.mushclient.com
Top
Posted by Nick Gammon   Australia  (23,133 posts)  Bio   Forum Administrator
Date Reply #24 on Tue 15 Dec 2009 09:41 PM (UTC)
Message
Under Windows Vista:


Time taken = 0.031614562743925


Vista with 1.8 GHz Intel Pentium Duo Processor
2 Gb RAM

MUSHclient 4.43
- Nick Gammon

www.gammon.com.au, www.mushclient.com
Top
Posted by Nick Gammon   Australia  (23,133 posts)  Bio   Forum Administrator
Date Reply #25 on Tue 15 Dec 2009 09:45 PM (UTC)
Message
Under Windows 7:


Time taken = 0.026684117736295


Windows 7 on Intel Core 2 Duo CPU 3.06 GHz
1 Gb RAM
(64 bits OS)

MUSHclient 4.43

(running on my iMac under VMware)
- Nick Gammon

www.gammon.com.au, www.mushclient.com
Top
Posted by Hanaisse   Canada  (114 posts)  Bio
Date Reply #26 on Tue 15 Dec 2009 09:49 PM (UTC)
Message
So I tried the 2nd test just for giggles. I'm not one of the ones that notice a delay, it's always been acceptable for me but then I have not used anything else to compare it to.

Windows XP Home SP3
Intel Core 2 Duo 3.166GHz
2GB RAM

MUSHclient 4.40

Time taken = 0.083629991226189

I was very surprised and did notice how choppy looking the output became. I guess I'm now in this category with the delay folks.

I'll try the debugging thing and post again.
aka: Hana
Owner in Training of: Fury of the Gods
alm-dev.org:4000
Top
Posted by Nick Gammon   Australia  (23,133 posts)  Bio   Forum Administrator
Date Reply #27 on Tue 15 Dec 2009 10:04 PM (UTC)

Amended on Tue 15 Dec 2009 10:08 PM (UTC) by Nick Gammon

Message
A slightly fairer test is this:



tstart = GetInfo (232)  -- high performance timer

for i = 1, 20 do
  Execute ("look")
  Execute ("score")
end -- for

tend = GetInfo (232)
print ("Time taken =", tend - tstart)


This changes Send to Execute, thus making the commands go through more of what usually happens when you type something in manually (eg. checking for script prefix, checking for aliases, checking for speedwalks).

In fact, the results should be very similar to manually typing if the following is true:


  • You don't have spellchecking enabled - obviously that might slow things down, particularly for longer lines

  • You don't have any plugins installed (which would check for the OnPluginCommandEntered plugin callback).

  • You don't have Auto-Say activated (which does extra processing)

- Nick Gammon

www.gammon.com.au, www.mushclient.com
Top
Posted by Nick Gammon   Australia  (23,133 posts)  Bio   Forum Administrator
Date Reply #28 on Tue 15 Dec 2009 10:06 PM (UTC)
Message
Hanaisse said:

I was very surprised and did notice how choppy looking the output became. I guess I'm now in this category with the delay folks.


However as I said, the choppy output may well be an artifact of the way the server is written. For example, it may pull incoming commands out of the queue every 0.5 seconds. Thus there is nothing you can do to make output faster.

Your results showed 83 ms for processing 40 commands, which is about 2 ms per command (nothing like 250 ms the original poster mentioned).
- Nick Gammon

www.gammon.com.au, www.mushclient.com
Top
Posted by Nick Gammon   Australia  (23,133 posts)  Bio   Forum Administrator
Date Reply #29 on Tue 15 Dec 2009 10:10 PM (UTC)

Amended on Tue 15 Dec 2009 10:11 PM (UTC) by Nick Gammon

Message
Using Execute rather than Send, and re-running on my Windows XP PC I usually use (the one I used first on this page), I got:


Time taken = 0.007344227284193


This is actually faster than my first results (which were 0.067820332478732 on that PC).
- Nick Gammon

www.gammon.com.au, www.mushclient.com
Top

The dates and times for posts above are shown in Universal Co-ordinated Time (UTC).

To show them in your local time you can join the forum, and then set the 'time correction' field in your profile to the number of hours difference between your location and UTC time.

121,110 views.

This is page 2, subject is 3 pages long:  [Previous page]  1  2 3  [Next page]

It is now over 60 days since the last post. This thread is closed.     Refresh page

Go to topic:           Search the forum

[Go to top] top

Information and images on this site are licensed under the Creative Commons Attribution 3.0 Australia License unless stated otherwise.

Home