Oh duh - I did everything under the sun except turn "UseCache" to true. As usual, you never figure out your own problem until you send out an email to the world.
Much better now.
Brian
On Feb 22, 2012, at 6:31 PM, Brian Bockelman wrote:
> Hi all,
>
> Are there asynchronous-read cache issues I should know about in 3.1?
>
> The output (debug level = 1) below shows where I issue a ReadV with 71 chunks, sleep for a second (to make sure the server responds), and prints out the contents of the cache.
>
> After printing out the contents of the cache, I immediately read the exact contents of the first few entries of the cache. The client log indicates that it went back out to the server.
>
> The code looks like this:
>
> // Prefetch into the cache (if any).
> if (m_client->ReadV(0, &offsets[0], &lengths[0], n) < 0) {
> edm::Exception ex(edm::errors::FileReadError);
> throw ex;
> }
> sleep(1);
> m_client->GetClientConn()->PrintCache();
> // Issue actual reads.
> IOSize total = 0;
> for (IOSize i = 0; i < n; ++i)
> {
> int s = m_client->Read(into[i].data(), offsets[i], lengths[i]);
> …
>
> The cache/read-ahead settings I used are:
>
> m_client->SetReadAheadStrategy(0);
> m_client->SetBlockReadTrimming(0);
> m_client->SetCacheParameters(-1, 0, 0);
>
> Anyone see anything "obvious" I'm doing wrong? If no, I'll dig more.
>
> Brian
>
> 120222 18:24:01 001 Xrd: ReqReadV: Requesting to read 71 chunks.
> 120222 18:24:01 001 Xrd: ReqReadV: Returning: total_len 10739731
> 120222 18:24:01 001 Xrd: ReadV: Excessive async readv size 13424663. Fixing cache size.
> 120222 18:24:01 16848 Xrd: ProcessUnsolicitedMsg: Incoming unsolicited response from streamid 4
> 120222 18:24:01 16848 Xrd: ProcessUnsolicitedMsg: Processing async response from streamid 4 father=1
> 120222 18:24:01 16848 Xrd: ProcessUnsolicitedMsg: Putting kXR_readV data into cache. len 1966240
> 120222 18:24:01 16848 Xrd: Cache: Submitting 360->196967 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 196968->393575 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 393576->590183 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 590184->786791 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 786792->983399 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 983400->1180007 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 1180008->1376615 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 1376616->1573223 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 1573224->1769831 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 1769832->1966439 to cache.
> 120222 18:24:01 16848 Xrd: ProcessUnsolicitedMsg: Incoming unsolicited response from streamid 4
> 120222 18:24:01 16848 Xrd: ProcessUnsolicitedMsg: Processing async response from streamid 4 father=1
> 120222 18:24:01 16848 Xrd: ProcessUnsolicitedMsg: Putting kXR_readV data into cache. len 1966240
> 120222 18:24:01 16848 Xrd: Cache: Submitting 1966440->2163047 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 2163048->2359655 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 2359656->2556263 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 2556264->2752871 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 2752872->2949479 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 2949480->3146087 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 3146088->3342695 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 3342696->3539303 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 3539304->3735911 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 3735912->3932519 to cache.
> 120222 18:24:01 16848 Xrd: ProcessUnsolicitedMsg: Incoming unsolicited response from streamid 4
> 120222 18:24:01 16848 Xrd: ProcessUnsolicitedMsg: Processing async response from streamid 4 father=1
> 120222 18:24:01 16848 Xrd: ProcessUnsolicitedMsg: Putting kXR_readV data into cache. len 1997858
> 120222 18:24:01 16848 Xrd: Cache: Submitting 3932520->4129127 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 4129128->4325735 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 4325736->4522343 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 4522344->4718951 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 4718952->4915559 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 4915560->5112167 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 5112168->5308775 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 5308776->5505383 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 5505384->5536985 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 5537764->5734371 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 5734372->5930979 to cache.
> 120222 18:24:01 16848 Xrd: ProcessUnsolicitedMsg: Incoming unsolicited response from streamid 4
> 120222 18:24:01 16848 Xrd: ProcessUnsolicitedMsg: Processing async response from streamid 4 father=1
> 120222 18:24:01 16848 Xrd: ProcessUnsolicitedMsg: Putting kXR_readV data into cache. len 2073502
> 120222 18:24:01 16848 Xrd: Cache: Submitting 5930980->6127587 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 6127588->6324195 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 6324196->6520803 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 6520804->6717411 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 6717412->6914019 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 6914020->7085720 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 7216971->7217663 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 7360659->7467076 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 7519223->7519932 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 7600901->7797508 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 7797509->7977539 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 8262674->8265352 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 8446084->8446711 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 8481421->8482683 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 8893583->8907505 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 9007528->9204135 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 9204136->9400743 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 9400744->9423047 to cache.
> 120222 18:24:01 16848 Xrd: ProcessUnsolicitedMsg: Incoming unsolicited response from streamid 4
> 120222 18:24:01 16848 Xrd: ProcessUnsolicitedMsg: Processing async response from streamid 4 father=1
> 120222 18:24:01 16848 Xrd: ProcessUnsolicitedMsg: Putting kXR_readV data into cache. len 1954115
> 120222 18:24:01 16848 Xrd: Cache: Submitting 9695526->9888175 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 9956070->10024962 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 10659786->10856393 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 10856394->10944615 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 10944945->11141552 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 11141553->11338160 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 11338161->11389968 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 11547044->11547186 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 11592419->11624884 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 11671050->11867657 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 11867658->12064265 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 12064266->12071205 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 12208733->12208882 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 12260125->12456732 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 12456733->12653340 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 12653341->12789671 to cache.
> 120222 18:24:01 16848 Xrd: ProcessUnsolicitedMsg: Incoming unsolicited response from streamid 4
> 120222 18:24:01 16848 Xrd: ProcessUnsolicitedMsg: Processing async response from streamid 4 father=1
> 120222 18:24:01 16848 Xrd: ProcessUnsolicitedMsg: Putting kXR_readV data into cache. len 782912
> 120222 18:24:01 16848 Xrd: Cache: Submitting 12835083->13013821 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 13082309->13278916 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 13278917->13475524 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 13475525->13538864 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 13562322->13583340 to cache.
> 120222 18:24:01 16848 Xrd: Cache: Submitting 13583511->13710012 to cache.
> 120222 18:24:02 001 Xrd: Cache: Cache Status --------------------------
> 120222 18:24:02 001 Xrd: Cache blk: 0Data block 360->196967
> 120222 18:24:02 001 Xrd: Cache blk: 1Data block 196968->393575
> 120222 18:24:02 001 Xrd: Cache blk: 2Data block 393576->590183
> 120222 18:24:02 001 Xrd: Cache blk: 3Data block 590184->786791
> 120222 18:24:02 001 Xrd: Cache blk: 4Data block 786792->983399
> 120222 18:24:02 001 Xrd: Cache blk: 5Data block 983400->1180007
> 120222 18:24:02 001 Xrd: Cache blk: 6Data block 1180008->1376615
> 120222 18:24:02 001 Xrd: Cache blk: 7Data block 1376616->1573223
> 120222 18:24:02 001 Xrd: Cache blk: 8Data block 1573224->1769831
> 120222 18:24:02 001 Xrd: Cache blk: 9Data block 1769832->1966439
> 120222 18:24:02 001 Xrd: Cache blk: 10Data block 1966440->2163047
> 120222 18:24:02 001 Xrd: Cache blk: 11Data block 2163048->2359655
> 120222 18:24:02 001 Xrd: Cache blk: 12Data block 2359656->2556263
> 120222 18:24:02 001 Xrd: Cache blk: 13Data block 2556264->2752871
> 120222 18:24:02 001 Xrd: Cache blk: 14Data block 2752872->2949479
> 120222 18:24:02 001 Xrd: Cache blk: 15Data block 2949480->3146087
> 120222 18:24:02 001 Xrd: Cache blk: 16Data block 3146088->3342695
> 120222 18:24:02 001 Xrd: Cache blk: 17Data block 3342696->3539303
> 120222 18:24:02 001 Xrd: Cache blk: 18Data block 3539304->3735911
> 120222 18:24:02 001 Xrd: Cache blk: 19Data block 3735912->3932519
> 120222 18:24:02 001 Xrd: Cache blk: 20Data block 3932520->4129127
> 120222 18:24:02 001 Xrd: Cache blk: 21Data block 4129128->4325735
> 120222 18:24:02 001 Xrd: Cache blk: 22Data block 4325736->4522343
> 120222 18:24:02 001 Xrd: Cache blk: 23Data block 4522344->4718951
> 120222 18:24:02 001 Xrd: Cache blk: 24Data block 4718952->4915559
> 120222 18:24:02 001 Xrd: Cache blk: 25Data block 4915560->5112167
> 120222 18:24:02 001 Xrd: Cache blk: 26Data block 5112168->5308775
> 120222 18:24:02 001 Xrd: Cache blk: 27Data block 5308776->5505383
> 120222 18:24:02 001 Xrd: Cache blk: 28Data block 5505384->5536985
> 120222 18:24:02 001 Xrd: Cache blk: 29Data block 5537764->5734371
> 120222 18:24:02 001 Xrd: Cache blk: 30Data block 5734372->5930979
> 120222 18:24:02 001 Xrd: Cache blk: 31Data block 5930980->6127587
> 120222 18:24:02 001 Xrd: Cache blk: 32Data block 6127588->6324195
> 120222 18:24:02 001 Xrd: Cache blk: 33Data block 6324196->6520803
> 120222 18:24:02 001 Xrd: Cache blk: 34Data block 6520804->6717411
> 120222 18:24:02 001 Xrd: Cache blk: 35Data block 6717412->6914019
> 120222 18:24:02 001 Xrd: Cache blk: 36Data block 6914020->7085720
> 120222 18:24:02 001 Xrd: Cache blk: 37Data block 7216971->7217663
> 120222 18:24:02 001 Xrd: Cache blk: 38Data block 7360659->7467076
> 120222 18:24:02 001 Xrd: Cache blk: 39Data block 7519223->7519932
> 120222 18:24:02 001 Xrd: Cache blk: 40Data block 7600901->7797508
> 120222 18:24:02 001 Xrd: Cache blk: 41Data block 7797509->7977539
> 120222 18:24:02 001 Xrd: Cache blk: 42Data block 8262674->8265352
> 120222 18:24:02 001 Xrd: Cache blk: 43Data block 8446084->8446711
> 120222 18:24:02 001 Xrd: Cache blk: 44Data block 8481421->8482683
> 120222 18:24:02 001 Xrd: Cache blk: 45Data block 8893583->8907505
> 120222 18:24:02 001 Xrd: Cache blk: 46Data block 9007528->9204135
> 120222 18:24:02 001 Xrd: Cache blk: 47Data block 9204136->9400743
> 120222 18:24:02 001 Xrd: Cache blk: 48Data block 9400744->9423047
> 120222 18:24:02 001 Xrd: Cache blk: 49Data block 9695526->9888175
> 120222 18:24:02 001 Xrd: Cache blk: 50Data block 9956070->10024962
> 120222 18:24:02 001 Xrd: Cache blk: 51Data block 10659786->10856393
> 120222 18:24:02 001 Xrd: Cache blk: 52Data block 10856394->10944615
> 120222 18:24:02 001 Xrd: Cache blk: 53Data block 10944945->11141552
> 120222 18:24:02 001 Xrd: Cache blk: 54Data block 11141553->11338160
> 120222 18:24:02 001 Xrd: Cache blk: 55Data block 11338161->11389968
> 120222 18:24:02 001 Xrd: Cache blk: 56Data block 11547044->11547186
> 120222 18:24:02 001 Xrd: Cache blk: 57Data block 11592419->11624884
> 120222 18:24:02 001 Xrd: Cache blk: 58Data block 11671050->11867657
> 120222 18:24:02 001 Xrd: Cache blk: 59Data block 11867658->12064265
> 120222 18:24:02 001 Xrd: Cache blk: 60Data block 12064266->12071205
> 120222 18:24:02 001 Xrd: Cache blk: 61Data block 12208733->12208882
> 120222 18:24:02 001 Xrd: Cache blk: 62Data block 12260125->12456732
> 120222 18:24:02 001 Xrd: Cache blk: 63Data block 12456733->12653340
> 120222 18:24:02 001 Xrd: Cache blk: 64Data block 12653341->12789671
> 120222 18:24:02 001 Xrd: Cache blk: 65Data block 12835083->13013821
> 120222 18:24:02 001 Xrd: Cache blk: 66Data block 13082309->13278916
> 120222 18:24:02 001 Xrd: Cache blk: 67Data block 13278917->13475524
> 120222 18:24:02 001 Xrd: Cache blk: 68Data block 13475525->13538864
> 120222 18:24:02 001 Xrd: Cache blk: 69Data block 13562322->13583340
> 120222 18:24:02 001 Xrd: Cache blk: 70Data block 13583511->13710012
> 120222 18:24:02 001 Xrd: Cache: -------------------------------------- fTotalByteCount = 10739731
> 120222 18:24:02 001 Xrd: Read: Read(offs=360, len=5536626)
> 120222 18:24:02 001 Xrd: SendGenCommand: Sending command ReadBuffer
> 120222 18:24:02 001 Xrd: ReadPartialAnswer: Reading a XrdClientMessage from the server [cmsstor168.fnal.gov:1093]...
> 120222 18:24:02 001 Xrd: Cache: Submitting 360->2097511 to cache.
>
>
> ########################################################################
> Use REPLY-ALL to reply to list
>
> To unsubscribe from the XROOTD-DEV list, click the following link:
> https://listserv.slac.stanford.edu/cgi-bin/wa?SUBED1=XROOTD-DEV&A=1
########################################################################
Use REPLY-ALL to reply to list
To unsubscribe from the XROOTD-DEV list, click the following link:
https://listserv.slac.stanford.edu/cgi-bin/wa?SUBED1=XROOTD-DEV&A=1
