[Tinymux] TinyMUX Profile of Shangrila for 30 minutes.

[Stephen Dennis]

The profiler report is too large to post to the list, but I'll post a my
summary of my interpretation of these results. I've sent copies of the
profiler output to a few individuals. They can vouch for my math or catch me
in error.

I started Shangrila, let it run with about 150-200 people connected for
approximately 30 minutes, and then @shutdown again. The profiler report
indicated 104.23 seconds out of approximately 30 minutes or 5.8% of the CPU.
It was higher than 5.8% while the game loaded, and then settled down to 1.5%
.

TinyMUX 2.4.0.20 <http://2.4.0.20/> Alpha was compiled with version
2.95.4of gcc -g -pg -O2 options. FreeBSD. Opteron 240 (
1.4 GHz). The session probably skews toward a larger-than-average rate of
disk access since the profile including the game startup with 200 people
connecting.

Firstly, I'm disappointed that the profiling overhead (.mcount()) appears to
be 31.1%.

__syscall() is next at 27.4%, and there isn't much that can be done short of
make cheaper calls and make fewer of them. Going MEMORY_BASED would probably
help as these calls are most-likely read requests. On the other hand,
starting the game is what is driving this to the top. Once the game is
started, this shouldn't matter as much as as it does here.

CHashPage::FindFirstKey (4.3%) - FindFirstKey takes 222ns per call. About
half the requests come from CHashFile access because the game is loading.
The other half come from hashfindLEN (not hashreplLEN, hashdeleteLEN,
hashaddLEN, or vattr_find_LEN). In other words, it is coming from function
name and command name lookups. I've looked at this function several times
already. I'm not sure I can make it faster.

memcpy (3.9%) - This take 77ns per call and almost all of the requests are
from CHashPage:HeapCopy() which is the routine for making a copy of an
attribute from inside a HashPage to the raw LBUF buffer. This also fits with
the game loading. It may be possible to elliminate some copying. Currently,
it's copied from the CHashPage to a TempRecord in attrcache.cpp and to the
attribute cache. The higher-level atr_get() calls make a third copy from
TempRecord into an LBUF-sized buffer which can be passed around freely in
the rest of the server.

AllocateEmptyPage (3.3%) and ReadCache (2.6%) - I can probably speed these
up, and for dbconvert operations, these two together form almost half of the
time spent unloading to a flatfile. The other half is in __syscall(). So, it
would benefit the netmux-mode with at most a 5% increase, but it would
benefit dbconvert-mode with at most a 50% increase.

select (1.6%) - Not much to say. There were 200 people connected.

mux_exec (1.5%), atr_match1 (1.1%), and parse_to_lite (1.1%) - When I
profile softcode on Win32, these three functions are typically at the top of
the list in this same order. The cost per call is 215ns, 5.6us, and 192ns,
respectively.

I've measured about 280,000 functions per second on my older machines at
home (450 MHz Xeon). The most one could expect on this Opteron 240 is
perhaps 800,000 functions per second. Adding the mux_exec(), FindFirstKey(),
and parse_to_lite() costs, you get 1.59 million, but the real answer is
probably somewhere below half of that.


Summary:

Shangrila has softcode, and players, but CPU-wise, it is not a demanding
game in the same class as BTMUX or Firan. I would expect to see parsing and
a few unforseen bottlenecks appear if the same test were performed on Firan.
But, for a game which pushes TinyMUX along a Shangrila vector, TinyMUX is
probably within 5% of topping out. After than 5%, the profile becomes flat
across all the functions. I'm not saying that it cannot be made faster, but
to accomplish faster, I think some fundamentally different approach would be
necessary.

Brazil
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://www.tinymux.org/pipermail/tinymux/attachments/20051011/2f18cf8f/attachment-0001.html