Slow remote reads in CMSSW_15_0_2

[davidlange6]

Production is using CMSSW_15_0_2 to run a remini-renano workflow and seeing rather poor CPU efficiencies.

An example log is /eos/cms/store/logs/prod/recent/PRODUCTION/pdmvserv_Run2024I_EGamma0_MINIv6NANOv15_250321_075704_7868/DataProcessing/cmsgwms-submit9.fnal.gov-2270711-1-log.tar

(others in that same area, this is one i grabbed)

Notably in the log there are quite a number of O(6-8 minute) pauses.

Running from a node CERN, copying the three input files takes a few minutes and then the workflow runs at reasonable efficiency (eg, it finished after 40 minutes while the job with remote file reads is 10% done after 70 minutes).

Running on the original files also illustrates pauses between events being processed (but not at the same event numbers as in the original job). The files in my example are:

xrdcp root://xrootd-cms.infn.it//store/data/Run2024I/EGamma0/AOD/PromptReco-v1/000/386/605/00000/9ad0cdbe-0470-45a8-90fa-9ccbd0ef4087.root .
xrdcp root://xrootd-cms.infn.it//store/data/Run2024I/EGamma0/AOD/PromptReco-v1/000/386/605/00000/5d7bb4b0-674e-4584-afe4-e71b63a95c1b.root .
xrdcp root://xrootd-cms.infn.it//store/data/Run2024I/EGamma0/AOD/PromptReco-v1/000/386/605/00000/6c68d214-3fd6-4b7b-9809-d0c8705a24cf.root .

(at T2_US_Vanderbilt, so not very close to cern...I believe the original job ran in Bari, which would be even further away)

[cmsbuild]

cms-bot internal usage

[cmsbuild]

A new Issue was created by @davidlange6.

@Dr15Jones, @antoniovilela, @makortel, @mandrenguyen, @rappoccio, @sextonkennedy, @smuzaffar can you please review it and eventually sign/assign? Thanks.

cms-bot commands are listed here

[makortel]

assign core

[cmsbuild]

New categories assigned: core

@Dr15Jones,@makortel,@smuzaffar you have been requested to review this Pull request/Issue and eventually sign? Thanks

[makortel]

From the log

• Job was configured to use 8 threads and 8 threads
• Total job time was ~15.4 hours, with total CPU time ~3 hours (22 minutes per core)
• Total non-module time was ~93 hours, or 11.6 hours per core

From the framework job report

  <PerformanceModule Metric="T2_US_Vanderbilt"  Module="XrdSiteStatistics" >
    <Metric Name="read-numOperations" Value="372162"/>
    <Metric Name="read-totalMegabytes" Value="1658.38"/>
    <Metric Name="read-totalMsecs" Value="5.17679e+07"/>
    <Metric Name="readv-numChunks" Value="29095"/>
    <Metric Name="readv-numOperations" Value="1228"/>
    <Metric Name="readv-totalMegabytes" Value="7187.62"/>
    <Metric Name="readv-totalMsecs" Value="1.10556e+06"/>
  </PerformanceModule>

Via regular reads, the job read 1.6 GB in 372k requests taking ~14 hours(!), translating to 4.6 kB and ~140 ms per request (33 kB/s).

Via vector reads, the job read 7 GB in 1228 requests taking ~18 minutes, translating to 5.9 MB and ~900 ms per request (6.5 MB/s).

[makortel]

According to _condor_stdout the job was ran on T2_IT_Bari.

According to the XrdSiteStatistics above the data was read from T2_US_Vanderbilt, and this is also confirmed from the cmsRun1-stdout.log that has many messages along

Deactivating xrootd-se30-vanderbilt.sites.opensciencegrid.org from active sources because its quality (1701) is higher than 260 and 4 times larger than the other active server xrootd-se34-vanderbilt.sites.opensciencegrid.org (177)

The _condor_stdout included

======== HTCondor jobAds start at Sat Mar 22 20:59:50 GMT 2025 ========
<cut>
  DESIRED_CMSDataLocations = "T2_US_Vanderbilt"

According to DAS the /EGamma0/Run2024I-PromptReco-v1/AOD dataset is available only on T2_US_Vanderbilt (in addition to T1_US_FNAL_Tape).

So it seems to me the job was reading the data over the Atlantic.

[makortel]

I'd nevertheless like to understand why the job read 1.6 GB via non-vector reads.

[makortel]

The cmsRun1-stdout.log lists the opened files along

22-Mar-2025 21:01:13 UTC  Successfully opened file root://xrootd-cms.infn.it//store/data/Run2024I/EGamma0/AOD/PromptReco-v1/000/386/605/00000/9ad0cdbe-0470-45a8-90fa-9ccbd0ef4087.root

The message includes the PFN, that is an URL for the redirector. We don't generally list the actual connections (sources in the XrdAdaptor terminology) in the log. With @Dr15Jones we think we should add a printout to the XrdAdaptor that tells the actual xrootd connection that was opened (i.e. each source that was created).

In this case the vanderbilt host names were visible in the log only because the XrdAdaptor's messages about deactivating sources because of poor quality.

We could also think of adding all the Source names (or URLs?) to the framework job report. @amaltaro @anpicci if we were to do that

• Would the information be useful for WM monitoring?
• If yes, is there a specific way we should express the information in the XML file?

[makortel]

Tagging @bbockelm @dynamic-entropy @osschar since the topic touches xrootd.

[makortel]

Here is another example (by @davidlange6 from https://mattermost.web.cern.ch/cms-o-and-c/pl/fxqgruof87re9rxdjqmtkcsseh)

looks like /eos/cms/store/logs/prod/recent/PRODUCTION/pdmvserv_Run2024I_EGamma0_MINIv6NANOv15_250321_075704_7868/DataProcessing/cmsgwms-submit9.fnal.gov-2271370-1-log.tar.gz

read remote from FNAL to Vanderbilt (so no Atlantic). Indeed is better but still quite worse than Phat's results above

   <Metric Name="TotalLoopCPU" Value="11336.1"/>
   <Metric Name="TotalLoopTime" Value="8034.73"/>

 <PerformanceModule Metric="T2_US_Vanderbilt"  Module="XrdSiteStatistics" >
   <Metric Name="read-numOperations" Value="341743"/>
   <Metric Name="read-totalMegabytes" Value="1361.04"/>
   <Metric Name="read-totalMsecs" Value="5.31354e+06"/>
   <Metric Name="readv-numChunks" Value="24999"/>
   <Metric Name="readv-numOperations" Value="1041"/>
   <Metric Name="readv-totalMegabytes" Value="6595.85"/>
   <Metric Name="readv-totalMsecs" Value="334857"/>
 </PerformanceModule>

The time spent in non-vector and vector reads are order of magnitude better than in #47750 (comment), but the metrics on non-vector reads (especially total latency of 1.5 hours in a 2.2 hour job) is still concerning.