outbound-gateway executes the MV command very slowly

Question

After we upgraded the version of Spring Integration from 4.2.13 to 5.3.1, SFTP Outbound Gateway would often execute the MV command for more than 30 seconds. We use inbound-stream-channel-adapter to fetch the file and then use outbound-gateway to move it to the Backup folder, below is our xml code snippet

<int:channel id="input">
    <int:queue />
</int:channel>
<int:channel id="output">
    <int:queue />
    <int:interceptors>
        <int:wire-tap channel="successHistory"/>
    </int:interceptors>
</int:channel>
<int-sftp:inbound-streaming-channel-adapter id="sftInboundAdapter"
                                            session-factory="cachingSftpSessionFactory"
                                            channel="input"
                                            remote-file-separator="/"
                                            remote-directory="/home/box">
    <int:poller fixed-delay="2000" max-messages-per-poll="1"/>
</int-sftp:inbound-streaming-channel-adapter>

<int:chain id="chain1" input-channel=" input" output-channel="output">
    <int:poller fixed-delay="1000"/>
    <int:stream-transformer charset="UTF-8"/>
    <int:header-enricher>
        <int:error-channel ref="error" overwrite="true"/>
        <int:header name="originalPayload" expression="payload"/>
    </int:header-enricher>
    <int-sftp:outbound-gateway session-factory="cachingSftpSessionFactory"
                               id="sftpOutboundGateway"
                               command="mv"
                               expression="headers.file_remoteDirectory+'/'+headers.file_remoteFile"
                               rename-expression="headers.file_remoteDirectory+'/backup/'+headers.file_remoteFile"
    >
            <int-sftp:request-handler-advice-chain>
                <ref bean="gatewayLogger"/>
            </int-sftp:request-handler-advice-chain>
        </int-sftp:outbound-gateway>
    <int:transformer expression="headers.originalPayload"/>
</int:chain>
<jms:outbound-channel-adapter channel="output" connection-factory="tibcoEmsConnectionFactory" destination="topic"/>

<bean id="sftpSessionFactory"
      class="org.springframework.integration.sftp.session.DefaultSftpSessionFactory">
    <property name="host" value="${sftp.host}"/>
    <property name="port" value="${sftp.port}"/>
    <property name="user" value="${sftp.user}"/>
    <property name="password" value="${sftp.password}"/>
    <property name="allowUnknownKeys" value="true"/>
    <property name="timeout" value="300000"/>
</bean>

<bean id="cachingSftpSessionFactory"
      class="org.springframework.integration.file.remote.session.CachingSessionFactory">
    <constructor-arg ref="sftpSessionFactory"/>
    <constructor-arg value="2"/>
    <property name="sessionWaitTimeout" value="300000"/>
</bean>

The Gateway Advice generated logs are as follows, the rename(MV) operation took more than 30 seconds

2020-07-07 12:20:16 INFO  [task-scheduler-8] gatewayLogger - ''int-sftp:outbound-gateway' with id='sftpOutboundGateway''@1346093219 - before:  {file_remoteHostPort=0.0.0.0, fileName=20200707115747609.xml, errorChannel=bean 'error', file_remoteDirectory=/home/box, originalPayload=<?xml version="1.0" encoding="UTF-8"?>

2020-07-07 12:20:48 INFO  [task-scheduler-8] gatewayLogger - ''int-sftp:outbound-gateway' with id='sftpOutboundGateway''@1346093219 - after:  org.springframework.integration.support.MessageBuilder@153944c0

As we use a chain for message processing, and session will be released by Stream transformer, if the gateway runs too long , then messages will be pend in queue and related session can’t be released, that will cause message stuck and the adapter will use up all sessions in cache.

Answer 1

It caused by org.springframework.integration.file.remote.RemoteFileUtils#makeDirectories, which is synchronized static method, when there are lots of (S)ftp move operation concurrently and slow speed of network, all requests of AbstractRemoteFileOutboundGateway#mv are queued and observed as very slow speed.

The method signature is as below:

public static synchronized <F> void makeDirectories(String path, Session<F> session, String remoteFileSeparator,
        Log logger) throws IOException {

Answer 2

I think SpringIntegration-5.3.1 has a bug in int-sftp:outbound-gateway as we can easily reproduce sftp gateway execute mv command with long time on certain machine (Our production)

however after we replaced gateway with our own activator, the mv command executed very very fast.

we replaced:

<int-sftp:outbound-gateway session-factory="cachingSftpSessionFactory"
                               id="sftpOutboundGateway"
                               command="mv"
                               expression="headers.file_remoteDirectory+'/'+headers.file_remoteFile"
                               rename-expression="headers.file_remoteDirectory+'/backup/'+headers.file_remoteFile"
    >

with:

  <int:header-enricher>
            <int:header name="PATH_FROM" expression="headers.file_remoteDirectory+'/'+headers.file_remoteFile"/>
            <int:header name="PATH_TO" expression="headers.file_remoteDirectory+'/backup/'+headers.file_remoteFile"/>
        </int:header-enricher>
        <int:service-activator ref="remoteFileRenameActivator"/>

and here is the source code of our remoteFileRenameActivator

@ServiceActivator
    public Message moveFile(Message message, @Header("PATH_FROM") String pathFrom, @Header("PATH_TO") String pathTo) throws IOException {
        try (Session session = sessionFactory.getSession();) {
            LOGGER.debug(contextName + " " + session.toString() + " is moving file from " + pathFrom + " to " + pathTo);
            session.rename(pathFrom, pathTo);
        }
        return message;
    }

The reason of why we think this is a bug because:

1. We upgraded Spring integration from 4.2.13 to 5.3.1, we didn't meet such problem in 4.2.13
2. After we replaced gateway's mv command with our own implemented mv command, mv command execution was not a bottleneck anymore.
3. The issue was still there after we changed QueueChannel to DirectChannel and increased the session quantity.
4. We run rename command by command line in client, it is also very fast

Answer 3

I think the problem is really how you use a CachingSessionFactory. Your cache with that <constructor-arg value="2"/> is too low, therefore there is a high chance of race condition for cached sessions.

You use this session factory in the <int-sftp:inbound-streaming-channel-adapter> which opens a session and keeps it out of the cache until the <int:stream-transformer>. But that happens already on the other thread because your input channel is a QueueChannel. This way you let a thread for <int-sftp:inbound-streaming-channel-adapter> to go and this one is able to take a new session (if any) from the cache. So, when the <int-sftp:outbound-gateway> turn comes, there probably no sessions in the cache to deal with.

Explain, please, why your cache is so low and why do you use QueueChannel just after an inbound polling channel adapter? Not related, but why do you use the QueueChannel for output destination as well?