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).
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 -------------- next part -------------- An HTML attachment was scrubbed... URL: <https://emu.freenetproject.org/pipermail/devl/attachments/20030517/59cbf422/attachment.html>
