(r6) FTSChannelDebugging < LCGTier2

Tags: view all tags
<!-- keep this as a security measure:
   * Set ALLOWTOPICCHANGE = Main.TWikiAdminGroup,Main.LCGAdminGroup
   * Set ALLOWTOPICRENAME = Main.TWikiAdminGroup,Main.LCGAdminGroup
   #uncomment this if you want the page only be viewable by the internal people
   * #Set ALLOWTOPICVIEW = Main.TWikiAdminGroup,Main.LCGAdminGroup
-->

---+!! FTS (STAR-CSCS) Channel debugging

In August the channel worked fine for some interactive tries. I configured !PhEDEx to use it and let it run a few days. The amount of errors was rather
large, so I switched back to srmcp after three days. Statistics and details about these tries (error messages according to sites) can be found here:
   * [[https://hypernews.cern.ch/HyperNews/CMS/get/phedexOps/12.html][first !PhEDEx via FTS experiences]].

An intermittent error condition observed sometimes is the FTS error reason "Failed to get proxy certificate from myproxy-fts.cern.ch . Reason is Error in bind()". Usually this works with the next try.

%TOC%

---++ Initial FTS channel settings

The initial settings of the channel were:
<verbatim>
glite-transfer-channel-list -s $FTSEP/ChannelManagement STAR-CSCS

Channel: STAR-CSCS
Between: * and CSCS-LCG2
State: Active
Contact: (null)
Bandwidth: 0
Nominal throughput: 0
Number of files: 10, streams: 10
Number of VO shares: 4
VO 'dteam' share is: 25
VO 'atlas' share is: 25
VO 'cms' share is: 25
VO 'lhcb' share is: 25
</verbatim>

---++ Test Cases
---+++ CSCS to CSCS copy %ICON{choice-no}%

copyjob file contains:

<verbatim>
srm://se01-lcg.projects.cscs.ch:8443/srm/managerv1?SFN=/dpm/projects.cscs.ch/home/cms/heartbeat/test.transfer
srm://se01-lcg.projects.cscs.ch:8443/srm/managerv1?SFN=/dpm/projects.cscs.ch/home/cms/local_tests/derek-local-copyjob.tst
</verbatim>

This transfer cannot be done with =srmcp= because DPM cannot act as a SRM source (see [[http://www.dcache.org/manuals/experts_docs/pushpull.html][this link]] for terminology). This should probably also prevent FTS from working, if it
needs to go via the SRM protocol.

FTS commands return the following diagnostics:

<verbatim>
glite-transfer-status -l -s $FTSEP/FileTransfer 16ca2477-4337-11db-a8b9-b90c0f5467b9

Active
  Source:      srm://se01-lcg.projects.cscs.ch:8443/srm/managerv1?SFN=/dpm/projects.cscs.ch/home/cms/heartbeat/test.transfer
  Destination: srm://se01-lcg.projects.cscs.ch:8443/srm/managerv1?SFN=/dpm/projects.cscs.ch/home/cms/local_tests/derek-local-copyjob.tst
  State:       Waiting
  Retries:     2
  Reason:       Getting filesize failed. a system call failed (Connection timed out)
  Duration:    0
</verbatim>

In the */var/log/srmv1/log* on our SE I see

<verbatim>
...
09/13 16:49:21  1460,8 getRequestStatus: request by /O=GRID-FR/C=CH/O=CSCS/OU=CC-LCG/CN=Derek
 Feichtinger from fts-fzk.gridka.de
09/13 16:49:21  1460,8 getRequestStatus: SRM98 - getRequestStatus 594707
09/13 16:49:21  1460,8 getRequestStatus: returns 0
09/13 16:49:21  1460,8 setFileStatus: request by /O=GRID-FR/C=CH/O=CSCS/OU=CC-LCG/CN=Derek Fe
ichtinger from fts-fzk.gridka.de
09/13 16:49:21  1460,8 setFileStatus: SRM98 - setFileStatus 594707 0 Running
09/13 16:49:21  1460,8 setFileStatus: returns 0
09/13 16:49:21  1460,8 ping: request by /O=GRID-FR/C=CH/O=CSCS/OU=CC-LCG/CN=Derek Feichtinger
 from fts-fzk.gridka.de
09/13 16:49:21  1460,8 ping: returns 0
09/13 16:49:21  1460,8 put: request by /O=GRID-FR/C=CH/O=CSCS/OU=CC-LCG/CN=Derek Feichtinger
from fts-fzk.gridka.de
09/13 16:49:21  1460,8 put: SRM98 - put 594711 594711
09/13 16:49:21  1460,8 put: SRM98 - put 0 srm://se01-lcg.projects.cscs.ch/dpm/projects.cscs.c
h/home/cms/local_tests/derek-local-copyjob.tst
09/13 16:49:22  1460,8 put: returns 0
09/13 16:49:22  1460,8 getRequestStatus: request by /O=GRID-FR/C=CH/O=CSCS/OU=CC-LCG/CN=Derek
 Feichtinger from fts-fzk.gridka.de
09/13 16:49:22  1460,8 getRequestStatus: SRM98 - getRequestStatus 594711
09/13 16:49:22  1460,8 getRequestStatus: returns 0
...
...
09/13 16:52:35  1460,8 setFileStatus: request by /O=GRID-FR/C=CH/O=CSCS/OU=CC-LCG/CN=Derek Fe
ichtinger from fts-fzk.gridka.de
09/13 16:52:35  1460,8 setFileStatus: SRM98 - setFileStatus 594707 0 Done
09/13 16:52:35  1460,8 setFileStatus: returns 0
09/13 16:52:35  1460,8 setFileStatus: request by /O=GRID-FR/C=CH/O=CSCS/OU=CC-LCG/CN=Derek Fe
ichtinger from fts-fzk.gridka.de
09/13 16:52:35  1460,8 setFileStatus: SRM98 - setFileStatus 594711 0 Done
09/13 16:52:35  1460,8 setFileStatus: dpm_putdone failed: No such file or directory
09/13 16:52:35  1460,8 setFileStatus: returns 12
...
(repeats many times)
</verbatim>

---+++ FZK to CSCS copy %ICON{choice-no}%

copyjob file contains:

<verbatim>
srm://gridka-dCache.fzk.de:8443/srm/managerv1?SFN=/pnfs/gridka.de/cms/disk-only/heartbeat/test.transfer
srm://se01-lcg.projects.cscs.ch:8443/srm/managerv1?SFN=/dpm/projects.cscs.ch/home/cms/local_tests/derek-fts-FZK-CSCS.tst
</verbatim>

Made sure that a copy using =srmcp -pushmode= is reproducibly successful.

Displays exactly same behavior as CSCS-CSCS copy. Same messages from =glite-transfer-status= and in */var/log/srmv1/log*


---+++ CSCS to CSCS copy with FTS number of streams changed to 1 %ICON{choice-yes}%

This worked at once with several tries by hand. It seems that the number of parallel streams is a parameter with lots of impact.

A lot of thanks to Jiri Chuboda for his ALICE/ATLAS [[https://twiki.cern.ch/twiki/bin/view/Main/PragueAndServiceChallenge4][SC4 pages]] for the Prague T2, which I found googling around.

So, FTS is somehow able to handle the fact that DPM can not act as a SRM source.

---+++ FZK to CSCS copy with FTS number of streams changed to 1 %ICON{choice-yes}%

Also this transfer worked at once with the new setting for the number of parallel streams.

---+++ !PhEDEx test with this setup

In transfers from IN2P3 I see about 50% failiures with these error messages (leading number indicates number of failures with this specific error):
<verbatim>
      2 T1_IN2P3_Load:  Failed Failed on SRM put: Failed SRM put on httpg://se01-lcg.projects.cscs.ch:8443/srm/managerv1 ;  Error is File exists;
      1 T1_IN2P3_Load:  Failed Transfer failed due to possible network problem - timed out.;
      1 T1_IN2P3_Load:  Failed Transfer failed. ERROR an end-of-file was reached;
     11 T1_IN2P3_Load:  Failed Transfer failed. ERROR the server sent an error response: 425 425 Can't open data connection. timed out() failed.;
</verbatim>
At least the errors seem to be now more uniform and not as in the first !PhEDEx test last month.

As can be seen from the following Ganglia graphs, the throuput for the downloads is at a maximum of ca. 20 MB/s. There is a very high degree of symmetric packet exchange involved based on the _packets graph_. It's a bit disturbing that we already see quite a bit of CPU_WAIT at this degree of load.

<br><img src="%ATTACHURLPATH%/network-20060915.gif" alt="network-20060915.gif" width='391' height='147' />
<br><img src="%ATTACHURLPATH%/packets-20060915.gif" alt="packets-20060915.gif" width='391' height='147' />
<br><img src="%ATTACHURLPATH%/cpu-20060915.gif" alt="cpu-20060915.gif" width='391' height='147' />

After 1 day (Sep 16):

<verbatim>
SITE STATISTICS:
==================
site: T1_CERN_Load (OK: 14 / FAILED: 5)   success rate: 73.6842105263158%
site: T1_IN2P3_Load (OK: 311 / FAILED: 155)   success rate: 66.7381974248927%

      1 T1_IN2P3_Load:  Failed Failed on SRM put: SRM getRequestStatus timed out on put;
      4 T1_IN2P3_Load:  Failed Transfer failed. ERROR an end-of-file was reached;
      5 T1_IN2P3_Load:  Failed Failed to get proxy certificate from myproxy-fts.cern.ch . Reason is Error in bind();
      6 T1_IN2P3_Load:  Failed Transfer failed due to possible network problem - timed out.;
      7 T1_IN2P3_Load:  Failed Failed on SRM put: SRM getRequestStatus timed out on put; also failing to do 'advisoryDelete' on target.;
     28 T1_IN2P3_Load:  Failed Failed on SRM put: Failed SRM put on httpg://se01-lcg.projects.cscs.ch:8443/srm/managerv1 ;  Error is File exists;
    104 T1_IN2P3_Load:  Failed Transfer failed. ERROR the server sent an error response: 425 425 Can't open data connection. timed out() failed.;
      5 T1_CERN_Load:  Failed Transfer failed. ERROR the server sent an error response: 425 425 Can't open data connection. timed out() failed.;

</verbatim>


<br /><img src="%ATTACHURLPATH%/cpu-20060916.gif" alt="cpu-20060916.gif" width='391' height='147' />
<br /><img src="%ATTACHURLPATH%/network-20060916.gif" alt="network-20060916.gif" width='391' height='147' />
<br /><img src="%ATTACHURLPATH%/packets-20060916.gif" alt="packets-20060916.gif" width='391' height='147' />


-- Main.DerekFeichtinger - 16 Sep 2006
Attachments
Topic attachments
I	Attachment	History	Action	Size	Date	Who
gif	cpu-20060915.gif	r2 r1	manage	13.5 K	2006-09-15 - 15:23	DerekFeichtinger
gif	cpu-20060916.gif	r1	manage	15.1 K	2006-09-16 - 14:58	DerekFeichtinger
gif	network-20060915.gif	r2 r1	manage	12.1 K	2006-09-15 - 15:23	DerekFeichtinger
gif	network-20060916.gif	r1	manage	14.3 K	2006-09-16 - 14:58	DerekFeichtinger
gif	packets-20060915.gif	r2 r1	manage	11.2 K	2006-09-15 - 15:22	DerekFeichtinger
gif	packets-20060916.gif	r1	manage	14.3 K	2006-09-16 - 14:59	DerekFeichtinger