Slow Unix socket write()s?
Locked
 
|
Folks - I've been doing a bit of load-testing on our servers and thing that surprised me was that even in moderate load tests the VM appears to be spending some 20-30% of its total execution time in Socket>>primSocket:sendData:startIndex:count:. This is roughly at a throughput of 10Mbit so nothing spectacular and a long ways before we hit our bandwidth limits. Given that the primitive in the Unix VM appears to be a vanilla call to write() I cannot possibly imagine what could cause this to take that much time. Also, all of these sends are guarded so socketSendDone: returned true prior to calling the send function (socketSendDone: takes about 2% total time in the profiles). Has anyone seen similar behavior or has an idea on how to find out what is going on? If this is known write() behavior I would definitely consider putting this into a pthread for our servers. It is currently by far the biggest bottleneck that I can see. Any ideas? Cheers, - Andreas |
|
|
mmm I do need to ask how do you know the measurements are correct? Well assuming you used message tally? I noticed in some benchmarking of object file out that it was saying 20% of the time in this case 24 SECONDS was taken up in SystemDictionary(IdentityDictionary)>>scanFor: in looking at why by adding a method to SystemDictionary and collecting information about the number of objects been looked for, and how many milliseconds I came to the conclusion that message tally was lying, there was only 90 some usages, accounting for 0 milliseconds. However I've not been able to determine why it's broken. System (System-adrian_lienhard.ducasse.207) btw In the past I've suggested using the message tracing VM and logging information in a more meaningful way since that hooks into the actual message send in the VM would give exact information. Plus it would leave less foot prints in the image since you aren't mixing another process (tally keeping) into the running of the smalltalk code. On 17-Feb-09, at 6:38 PM, Andreas Raab wrote: > Folks - > > I've been doing a bit of load-testing on our servers and thing that > surprised me was that even in moderate load tests the VM appears to > be spending some 20-30% of its total execution time in > Socket>>primSocket:sendData:startIndex:count:. This is roughly at a > throughput of 10Mbit so nothing spectacular and a long ways before > we hit our bandwidth limits. > > Given that the primitive in the Unix VM appears to be a vanilla call > to write() I cannot possibly imagine what could cause this to take > that much time. Also, all of these sends are guarded so > socketSendDone: returned true prior to calling the send function > (socketSendDone: takes about 2% total time in the profiles). > > Has anyone seen similar behavior or has an idea on how to find out > what is going on? If this is known write() behavior I would > definitely consider putting this into a pthread for our servers. It > is currently by far the biggest bottleneck that I can see. > > Any ideas? > > Cheers, > - Andreas -- = = = ======================================================================== John M. McIntosh <[hidden email]> Corporate Smalltalk Consulting Ltd. http://www.smalltalkconsulting.com = = = ======================================================================== |
|
|
Hi John - Good points, but we've long given up on MessageTally and replaced it with our own SystemProfiler and I do really trust its results. So the question still stands: Why could write() possibly be so slow? Cheers, - Andreas John M McIntosh wrote: > > mmm I do need to ask how do you know the measurements are correct? Well > assuming you used message tally? > > I noticed in some benchmarking of object file out that it was saying 20% > of the time in this case 24 SECONDS was taken up > in SystemDictionary(IdentityDictionary)>>scanFor: in looking at why > by adding a method to SystemDictionary and collecting information > about the number of objects been looked for, and how many milliseconds I > came to the conclusion that message tally was lying, there > was only 90 some usages, accounting for 0 milliseconds. > > However I've not been able to determine why it's broken. > System (System-adrian_lienhard.ducasse.207) btw > > > In the past I've suggested using the message tracing VM and logging > information in a more meaningful way since that hooks into the actual > message > send in the VM would give exact information. Plus it would leave less > foot prints in the image since you aren't mixing another process (tally > keeping) > into the running of the smalltalk code. > > > On 17-Feb-09, at 6:38 PM, Andreas Raab wrote: > >> Folks - >> >> I've been doing a bit of load-testing on our servers and thing that >> surprised me was that even in moderate load tests the VM appears to be >> spending some 20-30% of its total execution time in >> Socket>>primSocket:sendData:startIndex:count:. This is roughly at a >> throughput of 10Mbit so nothing spectacular and a long ways before we >> hit our bandwidth limits. >> >> Given that the primitive in the Unix VM appears to be a vanilla call >> to write() I cannot possibly imagine what could cause this to take >> that much time. Also, all of these sends are guarded so >> socketSendDone: returned true prior to calling the send function >> (socketSendDone: takes about 2% total time in the profiles). >> >> Has anyone seen similar behavior or has an idea on how to find out >> what is going on? If this is known write() behavior I would definitely >> consider putting this into a pthread for our servers. It is currently >> by far the biggest bottleneck that I can see. >> >> Any ideas? >> >> Cheers, >> - Andreas > > -- > =========================================================================== > John M. McIntosh <[hidden email]> > Corporate Smalltalk Consulting Ltd. http://www.smalltalkconsulting.com > =========================================================================== > > > |
Re: Slow Unix socket write()s?
|
|
In reply to this post by Andreas.Raab
On Tue, Feb 17, 2009 at 06:38:16PM -0800, Andreas Raab wrote: > > Folks - > > I've been doing a bit of load-testing on our servers and thing that > surprised me was that even in moderate load tests the VM appears to be > spending some 20-30% of its total execution time in > Socket>>primSocket:sendData:startIndex:count:. This is roughly at a > throughput of 10Mbit so nothing spectacular and a long ways before we > hit our bandwidth limits. > > Given that the primitive in the Unix VM appears to be a vanilla call to > write() I cannot possibly imagine what could cause this to take that > much time. Also, all of these sends are guarded so socketSendDone: > returned true prior to calling the send function (socketSendDone: takes > about 2% total time in the profiles). > > Has anyone seen similar behavior or has an idea on how to find out what > is going on? If this is known write() behavior I would definitely > consider putting this into a pthread for our servers. It is currently by > far the biggest bottleneck that I can see. > > Any ideas? Put a network analyzer (http://www.wireshark.org) on it and see what's going on at the TCP session level. There's a lot happening underneath the write() that is not visible, including the network stack, routers, TCP session protocol negotiation, etc. Looking through a log of the TCP session with wireshark can give an idea of what is really happening. If the VM is spending a lot of time blocking on writes to the network, and you know that network throughput is not the bottleneck, it suggests chattiness at the lower levels. This may be related to small chunks of data being written in separate write() calls. I'm assuming that the time is actually being spent in the write() calls. If that is not clear, you can confirm it by profiling the VM itself (gprof). You should positively verify this before putting effort into moving the writes into pthreads. Some characteristics of TCP sessions can be influenced by setting socket options (man setsockopt, man tcp). I have not experimented with this, but Socket>>setOption:value: can apparently be used to request these option settings. Try googling "tcp socket option tuning" for some more ideas. Dave |
|
|
In reply to this post by Andreas.Raab
and you have a pointer to this SystemProfiler somewhere? On 17-Feb-09, at 8:22 PM, Andreas Raab wrote: > Hi John - > > Good points, but we've long given up on MessageTally and replaced it > with our own SystemProfiler and I do really trust its results. So > the question still stands: Why could write() possibly be so slow? > > Cheers, > - Andreas -- = = = ======================================================================== John M. McIntosh <[hidden email]> Corporate Smalltalk Consulting Ltd. http://www.smalltalkconsulting.com = = = ======================================================================== |
|
|
Wouldn't do you much good without the VM changes. You'll have to wait until we have a Cog release. Cheers, - Andreas John M McIntosh wrote: > > and you have a pointer to this SystemProfiler somewhere? > > On 17-Feb-09, at 8:22 PM, Andreas Raab wrote: > >> Hi John - >> >> Good points, but we've long given up on MessageTally and replaced it >> with our own SystemProfiler and I do really trust its results. So the >> question still stands: Why could write() possibly be so slow? >> >> Cheers, >> - Andreas > > -- > =========================================================================== > John M. McIntosh <[hidden email]> > Corporate Smalltalk Consulting Ltd. http://www.smalltalkconsulting.com > =========================================================================== > > > |
«
Return to Squeak VM
|
1 view|%1 views
| Free forum by Nabble | Edit this page |