40s of overhead per file sounds standard to me. You will be glad/disheartened to here it applies to all sites. There may be a case that transfers between different types of SE are quicker, but needs to be investigated. There is a plan to use a feature in FTS which allows you to overcommit parts of the FTS cycle. Since you only have a single gridftp server, doe se this mean all connections are loaded serially and hence if a file transfer takes less than 40 seconds you actually end up with dead time?
Brian
-----Original Message-----
From: GRIDPP2: Deployment and support of SRM and local storage management [mailto:[log in to unmask]] On Behalf Of Christopher J. Walker
Sent: 07 April 2011 22:05
To: [log in to unmask]
Subject: Small files and fts
I've just had a look at the fts graph for QMUL.
Previously, I thought that gridftp pipelining was the answer to speeding small file transfers up. However, it looks like we may be able to get an appreciable speedup even without it.
I've attached graphs showing the transfer rate at about 30MB/s and the fact that there was a small queue of files ready to transfer.
grepping for fts in the gridftp-session.log, I get:
grep fts gridftp-session.log.1
> [3593] Wed Apr 6 06:13:08 2011 :: New connection from:
> lcgfts01.gridpp.rl.ac.uk:43002 [3593] Wed Apr 6 06:13:40 2011 ::
> Closed connection from lcgfts01.gridpp.rl.ac.uk:43002 [4502] Wed Apr
> 6 06:14:21 2011 :: New connection from: lcgfts01.gridpp.rl.ac.uk:44839
> [4502] Wed Apr 6 06:14:47 2011 :: Closed connection from
> lcgfts01.gridpp.rl.ac.uk:44839 [4547] Wed Apr 6 06:15:29 2011 :: New
> connection from: lcgfts01.gridpp.rl.ac.uk:46410 [4547] Wed Apr 6
> 06:15:52 2011 :: Closed connection from lcgfts01.gridpp.rl.ac.uk:46410
> [5488] Wed Apr 6 06:16:33 2011 :: New connection from:
> lcgfts01.gridpp.rl.ac.uk:58170 [5488] Wed Apr 6 06:16:58 2011 ::
> Closed connection from lcgfts01.gridpp.rl.ac.uk:58170 [5519] Wed Apr
> 6 06:17:39 2011 :: New connection from: lcgfts01.gridpp.rl.ac.uk:59548
> [5519] Wed Apr 6 06:18:11 2011 :: Closed connection from
> lcgfts01.gridpp.rl.ac.uk:59548 [6408] Wed Apr 6 06:18:52 2011 :: New
> connection from: lcgfts01.gridpp.rl.ac.uk:60688 [6408] Wed Apr 6
> 06:19:16 2011 :: Closed connection from lcgfts01.gridpp.rl.ac.uk:60688
> [6441] Wed Apr 6 06:19:57 2011 :: New connection from:
> lcgfts01.gridpp.rl.ac.uk:33426 [6441] Wed Apr 6 06:20:27 2011 ::
> Closed connection from lcgfts01.gridpp.rl.ac.uk:33426 [7328] Wed Apr
> 6 06:21:08 2011 :: New connection from: lcgfts01.gridpp.rl.ac.uk:54153
> [7328] Wed Apr 6 06:21:34 2011 :: Closed connection from
> lcgfts01.gridpp.rl.ac.uk:54153 [8206] Wed Apr 6 06:22:15 2011 :: New
> connection from: lcgfts01.gridpp.rl.ac.uk:56067 [8206] Wed Apr 6
> 06:22:41 2011 :: Closed connection from lcgfts01.gridpp.rl.ac.uk:56067
> [8237] Wed Apr 6 06:23:22 2011 :: New connection from:
> lcgfts01.gridpp.rl.ac.uk:57762 [8237] Wed Apr 6 06:23:52 2011 ::
> Closed connection from lcgfts01.gridpp.rl.ac.uk:57762 [9103] Wed Apr
> 6 06:24:31 2011 :: New connection from: lcgfts01.gridpp.rl.ac.uk:59344
> [9103] Wed Apr 6 06:25:09 2011 :: Closed connection from
> lcgfts01.gridpp.rl.ac.uk:59344 [9132] Wed Apr 6 06:25:49 2011 :: New
> connection from: lcgfts01.gridpp.rl.ac.uk:60820 [9132] Wed Apr 6
> 06:26:14 2011 :: Closed connection from lcgfts01.gridpp.rl.ac.uk:60820
> [10082] Wed Apr 6 06:26:55 2011 :: New connection from:
> lcgfts01.gridpp.rl.ac.uk:55347 [10082] Wed Apr 6 06:27:17 2011 ::
> Closed connection from lcgfts01.gridpp.rl.ac.uk:55347 [10107] Wed Apr
> 6 06:28:00 2011 :: New connection from: lcgfts01.gridpp.rl.ac.uk:56105
> [10107] Wed Apr 6 06:28:24 2011 :: Closed connection from
> lcgfts01.gridpp.rl.ac.uk:56105 [10998] Wed Apr 6 06:29:06 2011 :: New
> connection from: lcgfts01.gridpp.rl.ac.uk:56761 [10998] Wed Apr 6
> 06:29:31 2011 :: Closed connection from lcgfts01.gridpp.rl.ac.uk:56761
> [11026] Wed Apr 6 06:30:12 2011 :: New connection from:
> lcgfts01.gridpp.rl.ac.uk:58265 [11026] Wed Apr 6 06:30:37 2011 ::
> Closed connection from lcgfts01.gridpp.rl.ac.uk:58265 [11947] Wed Apr
> 6 06:31:18 2011 :: New connection from: lcgfts01.gridpp.rl.ac.uk:57632
> [11947] Wed Apr 6 06:32:20 2011 :: Closed connection from
> lcgfts01.gridpp.rl.ac.uk:57632 [12828] Wed Apr 6 06:33:01 2011 :: New
> connection from: lcgfts01.gridpp.rl.ac.uk:60042 [12828] Wed Apr 6
> 06:33:24 2011 :: Closed connection from lcgfts01.gridpp.rl.ac.uk:60042
> [12860] Wed Apr 6 06:34:07 2011 :: New connection from:
> lcgfts01.gridpp.rl.ac.uk:33401 [12860] Wed Apr 6 06:34:32 2011 ::
> Closed connection from lcgfts01.gridpp.rl.ac.uk:33401 [13730] Wed Apr
> 6 06:35:12 2011 :: New connection from: lcgfts01.gridpp.rl.ac.uk:34569
> [13730] Wed Apr 6 06:36:17 2011 :: Closed connection from
> lcgfts01.gridpp.rl.ac.uk:34569 [14607] Wed Apr 6 06:36:57 2011 :: New
> connection from: lcgfts01.gridpp.rl.ac.uk:34013 [14607] Wed Apr 6
> 06:37:24 2011 :: Closed connection from lcgfts01.gridpp.rl.ac.uk:34013
> [14644] Wed Apr 6 06:38:07 2011 :: New connection from:
> lcgfts01.gridpp.rl.ac.uk:35836 [14644] Wed Apr 6 06:38:32 2011 ::
> Closed connection from lcgfts01.gridpp.rl.ac.uk:35836 [15519] Wed Apr
> 6 06:39:18 2011 :: New connection from: lcgfts01.gridpp.rl.ac.uk:37533
> [15519] Wed Apr 6 06:39:43 2011 :: Closed connection from
> lcgfts01.gridpp.rl.ac.uk:37533 [16245] Wed Apr 6 06:40:25 2011 :: New
> connection from: lcgfts01.gridpp.rl.ac.uk:38635 [16245] Wed Apr 6
> 06:40:50 2011 :: Closed connection from lcgfts01.gridpp.rl.ac.uk:38635
> [16417] Wed Apr 6 06:41:34 2011 :: New connection from:
> lcgfts01.gridpp.rl.ac.uk:39256 [16417] Wed Apr 6 06:41:59 2011 ::
> Closed connection from lcgfts01.gridpp.rl.ac.uk:39256 [17289] Wed Apr
> 6 06:42:41 2011 :: New connection from: lcgfts01.gridpp.rl.ac.uk:39976
> [17289] Wed Apr 6 06:43:05 2011 :: Closed connection from
> lcgfts01.gridpp.rl.ac.uk:39976 [17312] Wed Apr 6 06:43:45 2011 :: New
> connection from: lcgfts01.gridpp.rl.ac.uk:40657 [17312] Wed Apr 6
> 06:44:09 2011 :: Closed connection from lcgfts01.gridpp.rl.ac.uk:40657
> [18181] Wed Apr 6 06:44:51 2011 :: New connection from:
> lcgfts01.gridpp.rl.ac.uk:41690 [18181] Wed Apr 6 06:45:13 2011 ::
> Closed connection from lcgfts01.gridpp.rl.ac.uk:41690 [18211] Wed Apr
> 6 06:45:58 2011 :: New connection from: lcgfts01.gridpp.rl.ac.uk:43328
> [18211] Wed Apr 6 06:46:26 2011 :: Closed connection from
> lcgfts01.gridpp.rl.ac.uk:43328 [19094] Wed Apr 6 06:47:09 2011 :: New
> connection from: lcgfts01.gridpp.rl.ac.uk:43963 [19094] Wed Apr 6
> 06:47:45 2011 :: Closed connection from lcgfts01.gridpp.rl.ac.uk:43963
> [19117] Wed Apr 6 06:48:26 2011 :: New connection from:
> lcgfts01.gridpp.rl.ac.uk:46069 [19117] Wed Apr 6 06:48:52 2011 ::
> Closed connection from lcgfts01.gridpp.rl.ac.uk:46069 [19991] Wed Apr
> 6 06:49:34 2011 :: New connection from: lcgfts01.gridpp.rl.ac.uk:47666
> [19991] Wed Apr 6 06:49:56 2011 :: Closed connection from
> lcgfts01.gridpp.rl.ac.uk:47666 [20885] Wed Apr 6 06:50:38 2011 :: New
> connection from: lcgfts01.gridpp.rl.ac.uk:49219 [20885] Wed Apr 6
> 06:51:04 2011 :: Closed connection from lcgfts01.gridpp.rl.ac.uk:49219
> [20912] Wed Apr 6 06:51:48 2011 :: New connection from:
> lcgfts01.gridpp.rl.ac.uk:39175 [20912] Wed Apr 6 06:52:10 2011 ::
> Closed connection from lcgfts01.gridpp.rl.ac.uk:39175 [21775] Wed Apr
> 6 06:52:53 2011 :: New connection from: lcgfts01.gridpp.rl.ac.uk:40474
> [21775] Wed Apr 6 06:53:18 2011 :: Closed connection from
> lcgfts01.gridpp.rl.ac.uk:40474 [21813] Wed Apr 6 06:54:01 2011 :: New
> connection from: lcgfts01.gridpp.rl.ac.uk:41845 [21813] Wed Apr 6
> 06:54:24 2011 :: Closed connection from lcgfts01.gridpp.rl.ac.uk:41845
So there is a huge delay - about 40s between closing one connection and starting the next.
Looking at one file in particular, I see from the srm logs (and omitting the details of the exact file transferred):
06:13:45.202 - INFO [XML-RPC-20] - srmLs:
06:13:45.202 - INFO [XML-RPC-20] - srmLs:
06:13:45.550 - INFO [pool-2-thread-7] - Handling PtG chunk for user DN:
06:13:45.626 - INFO [pool-2-thread-7] - Finished handling PtG chunk for user DN:
06:14:47.270 - INFO [XML-RPC-6] - srmReleaseFiles:
06:14:47.270 - INFO [XML-RPC-6] - srmReleaseFiles:
And from the gridftp-session.log for the same file, I see:
[4502] Wed Apr 6 06:14:21 2011 :: New connection from:
lcgfts01.gridpp.rl.ac.uk:44839
[4502] Wed Apr 6 06:14:22 2011 :: Starting to transfer
[4502] Wed Apr 6 06:14:46 2011 :: Finished transferring
So there's a delay of 30s between doing the PtG and actually opening the
gridftp connection.
Do other sites see this?
Is this apparent in the fts logs?
Is there anything that can be done to avoid this delay in FTS?
Chris
|