On Sat, May 17, 2003 at 02:05:44PM +0200, Niklas Bergh wrote:
> Well, I guess I just have to start the discussion myself then :)..
>
> According to the profiler 30% of the CPU is spent in
> NativeFSDirectory$NativeBuffer.setLastModified.. Well.. this method would
> seem to be called close to once for every single byte read from the
> datastorage. That method is called 2.5 million times, about samt number of
> times that NativeInputStream.read is called and pretty close to the amount
> of data that I was requesting from the node (2.5 megs). See the attached
> HTML if you want to study an example of this situation yourself (just expand
> the tree until you encounder the invalid percentages and then continue
> expanding).
Okay, the problem seems to be single byte reads from the datastore,
which happen when reading fields. This can be corrected by adding a
BufferedInputStream with a relatively small buffer (I'm using 8kB), in
FSDataStoreElement.KeyInputStream. We do NOT add a buffer at the
NativeFSDir level because it might interfere with CircularBuffer
implementation. In CVS unstable branch, please update and try again.
>
> This is an editer version of what the HTML shows:
> 1 inv. - freenet.node.StateChain.received
> 1 inv. - freenet.client.InternalClient$NewInternalGet.received
> 1 inv. - freenet.node.State.received
> 1 inv. - freenet.node.states.request.DataPending.receivedMessage
> 1 inv. - freenet.node.states.request.Pending.receivedRequestInitiator
> 1 inv. - freenet.node.states.request.Pending.searchData
> 1 inv. - freenet.node.ds.FSDataStore.getData
> 1 inv. - freenet.node.ds.FSDataStoreElement$KeyInputStreamImpl.
> 1 inv. - freenet.FieldSet.privParse
> 10 inv. - freenet.support.io.ReadInputStream.readToEOF
> 10 inv. - freenet.support.io.ReadInputStream.readToEOF
> 1168 inv. - freenet.support.io.ReadInputStream.readUTF
> 1168 inv. -
> freenet.fs.dir.NativeFSDirectory$NativeBuffer$NativeInputStream.read
> 1168 inv. - freenet.fs.dir.NativeFSDirectory$NativeBuffer.setLastModified
>
> According to this 1 searchData results in 1168 calls to the method
> NativeBuffer.setLastModified (which unconditinally calls the JVM method
> File.setModifiedTime). I think what we are looking at here is a request for
> an 1k large file (one of the activelink.xxx:s probably) which results in
> close to 1.2k of filesystem accesses (as I said in my previous mail I was
> seeing suprisingly much of the CPU spent in kernel time during my testing).
>
> If you study the code you will notice that the last part of the callstack
> above really ought to have looked like this:
> 1168 inv. -
> freenet.fs.dir.NativeFSDirectory$NativeBuffer$NativeInputStream.read
> 1168 inv. - freenet.fs.dir.NativeFSDirectory$NativeBuffer.touch
> 1168 inv. - freenet.fs.dir.NativeFSDirectory$NativeBuffer.setLastModified
>
> The reason for this discrepancy is that, as I said, I skipped
> instrumentation of and method less that 253 bytes in size and hence they
> wont show up in the profiler.
>
> Can someone verify this?
> /N
> <html>
> <head>
> <title>Thread call tree</title>
> <style>
> body{
> font: 10pt Verdana,sans-serif;
> color: navy;
> }
> .trigger{
> cursor: pointer;
> cursor: hand;
> }
> .branch{
> display: none;
> margin-left: 16px;
> }
> .folderopen{
> display: none;
> }
> .folderclosed{
> display: inline;
> }
> </style>
> <script language="JavaScript">
> function showBranch(branch){
> var objBranch = document.getElementById(branch).style;
> if(objBranch.display=="block")
> objBranch.display="none";
> else
> objBranch.display="block";
> }
> function swapFolderSign(sFolderName){
> objPlusSign = document.getElementById(sFolderName+"Plus");
>
> if(objPlusSign.style.display=="none")
> objPlusSign.style.display="inline"
> else
> objPlusSign.style.display="none"
>
> objMinusSign = document.getElementById(sFolderName+"Minus");
> if(objMinusSign.style.display=="inline")
> objMinusSign.style.display="none"
> else
> objMinusSign.style.display="inline"
> }
> </script>
> </head>
> <body>
> <div class="trigger"
> onClick="showBranch('branch1');swapFolderSign('folder1')">
> <span class = "folderclosed" id="folder1Plus">+</span><span class =
> "folderopen" id="folder1Minus">-</span>
> 100.00% - 510 ms - 1 inv. - 0 ms - 0.00% - freenet.Ticker$Event.run
> </div>
> <span class="branch" id="branch1">
> <div class="trigger"
> onClick="showBranch('branch2');swapFolderSign('folder2')">
> <span class = "folderclosed" id="folder2Plus">+</span><span class =
> "folderopen" id="folder2Minus">-</span>
> 100.00% - 510 ms - 1 inv. - 0 ms - 0.00% -
> freenet.node.StandardMessageHandler.handle
> </div>
> <span class="branch" id="branch2">
> <div class="trigger"
> onClick="showBranch('branch3');swapFolderSign('folder3')">
> <span class = "folderclosed" id="folder3Plus">+</span><span class =
> "folderopen" id="folder3Minus">-</span>
> 100.00% - 510 ms - 1 inv. - 0 ms - 0.00% -
> freenet.node.StandardMessageHandler$Ticket.received
> </div>
> <span class="branch" id="branch3">
> <div class="trigger"
> onClick="showBranch('branch4');swapFolderSign('folder4')">
> <span class = "folderclosed" id="folder4Plus">+</span><span class =
> "folderopen" id="folder4Minus">-</span>
> 100.00% - 510 ms - 1 inv. - 0 ms - 0.00% -
> freenet.node.StandardMessageHandler$Ticket.run
> </div>
> <span class="branch" id="branch4">
> <div class="trigger"
> onClick="showBranch('branch5');swapFolderSign('folder5')">
> <span class = "folderclosed" id="folder5Plus">+</span><span class =
> "folderopen" id="folder5Minus">-</span>
> 100.00% - 510 ms - 1 inv. - 0 ms - 0.00% - freenet.node.StateChain.received
> </div>
> <span class="branch" id="branch5">
> <div class="trigger"
> onClick="showBranch('branch6');swapFolderSign('folder6')">
> <span class = "folderclosed" id="folder6Plus">+</span><span class =
> "folderopen" id="folder6Minus">-</span>
> 100.00% - 510 ms - 1 inv. - 0 ms - 0.00% - freenet.node.StateChain.received
> </div>
> <span class="branch" id="branch6">
> <div class="trigger"
> onClick="showBranch('branch7');swapFolderSign('folder7')">
> <span class = "folderclosed" id="folder7Plus">+</span><span class =
> "folderopen" id="folder7Minus">-</span>
> 13246.67% - 67558 ms - 1 inv. - 0 ms - 0.00% -
> freenet.client.InternalClient$NewInternalGet.received
> </div>
> <span class="branch" id="branch7">
> <div class="trigger"
> onClick="showBranch('branch8');swapFolderSign('folder8')">
> <span class = "folderclosed" id="folder8Plus">+</span><span class =
> "folderopen" id="folder8Minus">-</span>
> 13246.67% - 67558 ms - 1 inv. - 0 ms - 0.00% - freenet.node.State.received
> </div>
> <span class="branch" id="branch8">
> <div class="trigger"
> onClick="showBranch('branch9');swapFolderSign('folder9')">
> <span class = "folderclosed" id="folder9Plus">+</span><span class =
> "folderopen" id="folder9Minus">-</span>
> 13246.67% - 67558 ms - 1 inv. - 0 ms - 0.00% -
> freenet.node.states.request.DataPending.receivedMessage
> </div>
> <span class="branch" id="branch9">
> <div class="trigger"
> onClick="showBranch('branch10');swapFolderSign('folder10')">
> <span class = "folderclosed" id="folder10Plus">+</span><span class =
> "folderopen" id="folder10Minus">-</span>
> 13246.67% - 67558 ms - 1 inv. - 0 ms - 0.00% -
> freenet.node.states.request.Pending.receivedRequestInitiator
> </div>
> <span class="branch" id="branch10">
> <div class="trigger"
> onClick="showBranch('branch11');swapFolderSign('folder11')">
> <span class = "folderclosed" id="folder11Plus">+</span><span class =
> "folderopen" id="folder11Minus">-</span>
> 13246.67% - 67558 ms - 1 inv. - 0 ms - 0.00% -
> freenet.node.states.request.Pending.searchData
> </div>
> <span class="branch" id="branch11">
> <div class="trigger"
> onClick="showBranch('branch12');swapFolderSign('folder12')">
> <span class = "folderclosed" id="folder12Plus">+</span><span class =
> "folderopen" id="folder12Minus">-</span>
> 13246.67% - 67558 ms - 1 inv. - 0 ms - 0.00% -
> freenet.node.ds.FSDataStore.getData
> </div>
> <span class="branch" id="branch12">
> <div class="trigger"
> onClick="showBranch('branch13');swapFolderSign('folder13')">
> <span class = "folderclosed" id="folder13Plus">+</span><span class =
> "folderopen" id="folder13Minus">-</span>
> 13238.63% - 67517 ms - 1 inv. - 0 ms - 0.00% -
> freenet.node.ds.FSDataStoreElement$KeyInputStreamImpl.<init>
> </div>
> <span class="branch" id="branch13">
> <div class="trigger"
> onClick="showBranch('branch14');swapFolderSign('folder14')">
> <span class = "folderclosed" id="folder14Plus">+</span><span class =
> "folderopen" id="folder14Minus">-</span>
> 13217.06% - 67407 ms - 1 inv. - 0 ms - 0.00% - freenet.FieldSet.privParse
> </div>
> <span class="branch" id="branch14">
> <div class="trigger"
> onClick="showBranch('branch15');swapFolderSign('folder15')">
> <span class = "folderclosed" id="folder15Plus">+</span><span class =
> "folderopen" id="folder15Minus">-</span>
> 13217.06% - 67407 ms - 10 inv. - 0 ms - 0.00% -
> freenet.support.io.ReadInputStream.readToEOF
> </div>
> <span class="branch" id="branch15">
> <div class="trigger"
> onClick="showBranch('branch16');swapFolderSign('folder16')">
> <span class = "folderclosed" id="folder16Plus">+</span><span class =
> "folderopen" id="folder16Minus">-</span>
> 13217.06% - 67407 ms - 10 inv. - 0 ms - 0.00% -
> freenet.support.io.ReadInputStream.readToEOF
> </div>
> <span class="branch" id="branch16">
> <div class="trigger"
> onClick="showBranch('branch17');swapFolderSign('folder17')">
> <span class = "folderclosed" id="folder17Plus">+</span><span class =
> "folderopen" id="folder17Minus">-</span>
> 13217.06% - 67407 ms - 1168 inv. - 10 ms - 1.96% -
> freenet.support.io.ReadInputStream.readUTF
> </div>
> <span class="branch" id="branch17">
> <div class="trigger"
> onClick="showBranch('branch18');swapFolderSign('folder18')">
> <span class = "folderclosed" id="folder18Plus">+</span><span class =
> "folderopen" id="folder18Minus">-</span>
> 13215.10% - 67397 ms - 1168 inv. - 21919 ms - 4297.84% -
> freenet.fs.dir.NativeFSDirectory$NativeBuffer$NativeInputStream.read
> </div>
> <span class="branch" id="branch18">
> <div class="trigger"
> onClick="showBranch('branch19');swapFolderSign('folder19')">
> <span class = "folderclosed" id="folder19Plus">+</span><span class =
> "folderopen" id="folder19Minus">-</span>
> 8905.49% - 45418 ms - 1168 inv. - 44956 ms - 8814.90% -
> freenet.fs.dir.NativeFSDirectory$NativeBuffer.setLastModified
> </div>
> <span class="branch" id="branch19">
> <div class="trigger"
> onClick="showBranch('branch20');swapFolderSign('folder20')">
> <span class = "folderclosed" id="folder20Plus">+</span><span class =
> "folderopen" id="folder20Minus">-</span>
> 50.98% - 260 ms - 1167 inv. - 0 ms - 0.00% -
> freenet.fs.dir.NativeFSDirectory$NativeBuffer.getFile
> </div>
> <span class="branch" id="branch20">
> <div class="trigger"
> onClick="showBranch('branch21');swapFolderSign('folder21')">
> <span class = "folderclosed" id="folder21Plus">+</span><span class =
> "folderopen" id="folder21Minus">-</span>
> 50.98% - 260 ms - 1167 inv. - 260 ms - 50.98% -
> freenet.fs.dir.NativeFSDirectory.getFile
> </div>
> <span class="branch" id="branch21">
> 1.96% - 10 ms - 116 inv. - 10 ms - 1.96% -
> freenet.support.Fields.bytesToHex<br/>
> </span>
> </span>
> <div class="trigger"
> onClick="showBranch('branch23');swapFolderSign('folder23')">
> <span class = "folderclosed" id="folder23Plus">+</span><span class =
> "folderopen" id="folder23Minus">-</span>
> 33.53% - 171 ms - 2334 inv. - 41 ms - 8.04% -
> freenet.fs.dir.NativeFSDirectory.verifyList
> </div>
> <span class="branch" id="branch23">
> 25.49% - 130 ms - 2334 inv. - 80 ms - 15.69% - freenet.crypt.Yarrow.next<br/>
> </span>
> <div class="trigger"
> onClick="showBranch('branch25');swapFolderSign('folder25')">
> <span class = "folderclosed" id="folder25Plus">+</span><span class =
> "folderopen" id="folder25Minus">-</span>
> 4.12% - 21 ms - 491 inv. - 0 ms - 0.00% -
> freenet.fs.dir.NativeFSDirectory$NativeBuffer.setLastModifiedAlreadyOut
> </div>
> <span class="branch" id="branch25">
> <div class="trigger"
> onClick="showBranch('branch26');swapFolderSign('folder26')">
> <span class = "folderclosed" id="folder26Plus">+</span><span class =
> "folderopen" id="folder26Minus">-</span>
> 4.12% - 21 ms - 491 inv. - 0 ms - 0.00% -
> freenet.fs.dir.NativeFSDirectory.verifyList
> </div>
> <span class="branch" id="branch26">
> <div class="trigger"
> onClick="showBranch('branch27');swapFolderSign('folder27')">
> <span class = "folderclosed" id="folder27Plus">+</span><span class =
> "folderopen" id="folder27Minus">-</span>
> 4.12% - 21 ms - 491 inv. - 0 ms - 0.00% - freenet.crypt.Yarrow.next
> </div>
> <span class="branch" id="branch27">
> 4.12% - 21 ms - 173 inv. - 21 ms - 4.12% -
> freenet.crypt.ciphers.Rijndael_Algorithm.blockEncrypt<br/>
> </span>
> </span>
> </span>
> </span>
> 27.65% - 141 ms - 1192 inv. - 141 ms - 27.65% -
> freenet.fs.dir.NativeFSDirectory$NativeBuffer$NativeInputStream.dead<br/>
> 9.80% - 50 ms - 997 inv. - 20 ms - 3.92% -
> freenet.fs.dir.NativeFSDirectory$NativeBuffer.maxLen<br/>
> </span>
> </span>
> </span>
> </span>
> </span>
> <div class="trigger"
> onClick="showBranch('branch31');swapFolderSign('folder31')">
> <span class = "folderclosed" id="folder31Plus">+</span><span class =
> "folderopen" id="folder31Minus">-</span>
> 21.57% - 110 ms - 1 inv. - 0 ms - 0.00% -
> freenet.fs.dir.NativeFSDirectory$NativeBuffer.getInputStream
> </div>
> <span class="branch" id="branch31">
> <div class="trigger"
> onClick="showBranch('branch32');swapFolderSign('folder32')">
> <span class = "folderclosed" id="folder32Plus">+</span><span class =
> "folderopen" id="folder32Minus">-</span>
> 15.69% - 80 ms - 1 inv. - 0 ms - 0.00% -
> freenet.fs.dir.NativeFSDirectory$NativeBuffer.open
> </div>
> <span class="branch" id="branch32">
> <div class="trigger"
> onClick="showBranch('branch33');swapFolderSign('folder33')">
> <span class = "folderclosed" id="folder33Plus">+</span><span class =
> "folderopen" id="folder33Minus">-</span>
> 15.69% - 80 ms - 1 inv. - 80 ms - 15.69% -
> freenet.fs.dir.NativeFSDirectory$NativeBuffer.setLastModified
> </div>
> <span class="branch" id="branch33">
> <div class="trigger"
> onClick="showBranch('branch34');swapFolderSign('folder34')">
> <span class = "folderclosed" id="folder34Plus">+</span><span class =
> "folderopen" id="folder34Minus">-</span>
> 1.96% - 10 ms - 1 inv. - 0 ms - 0.00% -
> freenet.fs.dir.NativeFSDirectory$NativeBuffer.getFile
> </div>
> <span class="branch" id="branch34">
> 1.96% - 10 ms - 1 inv. - 10 ms - 1.96% -
> freenet.fs.dir.NativeFSDirectory.getFile<br/>
> </span>
> </span>
> </span>
> 5.88% - 30 ms - 1 inv. - 30 ms - 5.88% -
> freenet.fs.dir.NativeFSDirectory$NativeBuffer.setLastModified<br/>
> </span>
> </span>
> 8.04% - 41 ms - 1 inv. - 41 ms - 8.04% -
> freenet.fs.dir.NativeFSDirectory$NativeBuffer.setLastModified<br/>
> </span>
> </span>
> </span>
> </span>
> </span>
> </span>
> <div class="trigger"
> onClick="showBranch('branch38');swapFolderSign('folder38')">
> <span class = "folderclosed" id="folder38Plus">+</span><span class =
> "folderopen" id="folder38Minus">-</span>
> 100.00% - 510 ms - 1 inv. - 0 ms - 0.00% -
> freenet.node.states.data.SendData.received
> </div>
> <span class="branch" id="branch38">
> <div class="trigger"
> onClick="showBranch('branch39');swapFolderSign('folder39')">
> <span class = "folderclosed" id="folder39Plus">+</span><span class =
> "folderopen" id="folder39Minus">-</span>
> 82.35% - 420 ms - 1 inv. - 0 ms - 0.00% -
> freenet.node.ds.FSDataStoreElement$KeyInputStreamImpl.close
> </div>
> <span class="branch" id="branch39">
> <div class="trigger"
> onClick="showBranch('branch40');swapFolderSign('folder40')">
> <span class = "folderclosed" id="folder40Plus">+</span><span class =
> "folderopen" id="folder40Minus">-</span>
> 82.35% - 420 ms - 1 inv. - 170 ms - 33.33% -
> freenet.fs.dir.NativeFSDirectory$NativeBuffer$NativeInputStream.close
> </div>
> <span class="branch" id="branch40">
> 49.02% - 250 ms - 1 inv. - 250 ms - 49.02% -
> freenet.fs.dir.NativeFSDirectory$NativeBuffer.close<br/>
> </span>
> </span>
> <div class="trigger"
> onClick="showBranch('branch42');swapFolderSign('folder42')">
> <span class = "folderclosed" id="folder42Plus">+</span><span class =
> "folderopen" id="folder42Minus">-</span>
> 17.65% - 90 ms - 1 inv. - 10 ms - 1.96% -
> freenet.fs.dir.NativeFSDirectory$NativeBuffer$NativeInputStream.read
> </div>
> <span class="branch" id="branch42">
> 15.69% - 80 ms - 1 inv. - 80 ms - 15.69% -
> freenet.fs.dir.NativeFSDirectory$NativeBuffer.setLastModified<br/>
> </span>
> </span>
> <div class="trigger"
> onClick="showBranch('branch44');swapFolderSign('folder44')">
> <span class = "folderclosed" id="folder44Plus">+</span><span class =
> "folderopen" id="folder44Minus">-</span>
> 1.96% - 10 ms - 1 inv. - 0 ms - 0.00% - freenet.node.State.received
> </div>
> <span class="branch" id="branch44">
> <div class="trigger"
> onClick="showBranch('branch45');swapFolderSign('folder45')">
> <span class = "folderclosed" id="folder45Plus">+</span><span class =
> "folderopen" id="folder45Minus">-</span>
> 1.96% - 10 ms - 1 inv. - 0 ms - 0.00% -
> freenet.node.states.request.SendingReply.receivedMessage
> </div>
> <span class="branch" id="branch45">
> <div class="trigger"
> onClick="showBranch('branch46');swapFolderSign('folder46')">
> <span class = "folderclosed" id="folder46Plus">+</span><span class =
> "folderopen" id="folder46Minus">-</span>
> 1.96% - 10 ms - 1 inv. - 0 ms - 0.00% -
> freenet.node.rt.TreeRouting.getNextRoute
> </div>
> <span class="branch" id="branch46">
> <div class="trigger"
> onClick="showBranch('branch47');swapFolderSign('folder47')">
> <span class = "folderclosed" id="folder47Plus">+</span><span class =
> "folderopen" id="folder47Minus">-</span>
> 1.96% - 10 ms - 1 inv. - 0 ms - 0.00% - freenet.crypt.CryptoKey.fingerprint
> </div>
> <span class="branch" id="branch47">
> 1.96% - 10 ms - 1 inv. - 10 ms - 1.96% - freenet.crypt.SHA1.update<br/>
> </span>
> </span>
> </span>
> </span>
> </span>
> </span>
> </span>
> </span>
> </span>
> </span>
> </body>
> </html>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-signature
Size: 189 bytes
Desc: not available
URL:
<https://emu.freenetproject.org/pipermail/devl/attachments/20030517/ea67589c/attachment.pgp>
