Slowness in 0.32.1-SNAPSHOT compared to 0.32.0 release

[brenttyler]

In testing my recent Pull Request #775 for Issue #700, I came across some weird slowness compared to the old v0.23 jar we had been using for years. Pulling my hair out thinking it was something I had done, I decided to directly compare the official 0.32.0 release and the 0.32.1-SNAPSHOT (as it is today). Here are my sample code and findings:

    public void execute(String host, int port, String user, String pass, File file) throws Throwable {
        try (SSHClient ssh = new SSHClient()) {
            ssh.addHostKeyVerifier(new PromiscuousVerifier());
            ssh.connect(host, port);
            ssh.authPassword(user, pass);
            
            try (SFTPClient sftp = ssh.newSFTPClient()) {
                final long startTime = System.nanoTime();
                sftp.get(file.getName(), file.getName());
                final double timeSeconds = TimeUnit.NANOSECONDS.toMillis (System.nanoTime() - startTime) / 1000.0;
                final double sizeKiB = file.length() / 1024.0;
                log.info(String.format("%1$,.1f KiB transferred in %2$,.1f seconds (%3$,.2f KiB/s)", sizeKiB, timeSeconds, (sizeKiB / timeSeconds)));
            }
        }
    }

I have logback set to info for this, hence the copied log.info() from StringCopier.copy(). Here are the results:

sshj-0.32.0.jar:
18:41:04 [main] INFO n.s.sshj.transport.random.JCERandom - Creating new SecureRandom.
18:41:04 [main] INFO n.s.sshj.transport.TransportImpl - Client identity string: SSH-2.0-SSHJ_0.32.0
18:41:04 [main] INFO n.s.sshj.transport.TransportImpl - Server identity string: SSH-2.0-OpenSSH_7.2p2 Ubuntu-4ubuntu2.10
18:41:05 [main] INFO n.s.s.c.c.direct.SessionChannel - Will request sftp subsystem
18:49:05 [main] WARN net.schmizz.sshj.xfer.FileSystemFile - Could not set permissions for <file> to 1b0
18:49:05 [main] INFO sshj.resume.test2.SlownessTest - 11,161,746.5 KiB transferred in 480.8 seconds (23,215.57 KiB/s)
18:49:05 [main] INFO n.s.sshj.transport.TransportImpl - Disconnected - BY_APPLICATION

sshj-0.32.1-SNAPSHOT.jar:
18:49:42 [main] INFO n.s.sshj.transport.random.JCERandom - Creating new SecureRandom.
18:49:42 [main] INFO n.s.sshj.transport.TransportImpl - Client identity string: SSH-2.0-SSHJ_0.32.1_SNAPSHOT
18:49:42 [main] INFO n.s.sshj.transport.TransportImpl - Server identity string: SSH-2.0-OpenSSH_7.2p2 Ubuntu-4ubuntu2.10
18:49:43 [main] INFO n.s.s.c.c.direct.SessionChannel - Will request sftp subsystem
21:03:35 [main] WARN net.schmizz.sshj.xfer.FileSystemFile - Could not set permissions for <file> to 1b0
21:03:35 [main] INFO sshj.resume.test2.SlownessTest - 11,161,746.5 KiB transferred in 8,032.3 seconds (1,389.61 KiB/s)
21:03:35 [main] INFO n.s.sshj.transport.TransportImpl - Disconnected - BY_APPLICATION

This was done without compression as well. As you can see, 0.32.1-SNAPSHOT is slower by a factor of 16.7x. I am not familiar enough with the code base or the technology behind it to have a valid opinion on what is going on, but I figured it was worth pointing out to someone who might.

I have since replicated my #775 changes on a branch from the 0.32.0 tag and validated that it works as expected. The only difference between my two almost-identical branches is that against 0.32.0 I didn't need to modify RemoteFile.ReadAheadRemoteFileInputStream to add a (int, long) constructor which, under 0.32.1-SNAPSHOT, merely passed-through to the (int, long, long) constructor because in 0.32.0 it was already there. (apologies for the very confusing sentence, but I'm trying to be detailed here as I don't 100% know what I'm talking about).

It might be worth looking at recent changes to RemoteFile.ReadAheadRemoteFileInputStream, but that's just a complete guess merely based on my two branches.

You can see these at my fork https://github.com/brenttyler/sshj on the issue-700 branch (#775) and the 0.32.0-issue-700 branches (no Pull Request).

[vladimirlagunov]

Hi! Could you try to find the problematic commit via git bisect?

[brenttyler]

Bisect confirms that the problem was introduced in #769 as the previous commit for #756 behaves properly.

[vladimirlagunov]

Well, I'll take a look.

[brenttyler]

I wish I could help more, but I don't have the expertise around that process to have an informed opinion. If it helps, we deal in very large files, for instance the one I'm testing with is 10.64 GB and not even the largest. These sizes and the fact that our users are sometimes uploading files from places with shoddy connections (hotels, hot spots, etc) made the ability to resume a high priority for us.

[vladimirlagunov]

@brenttyler could you verify the patch from #778, please? Also, check that downloaded files are not corrupted. Although I verified the changes on various decent test suites, some bug can exist.

[brenttyler]

@vladimirlagunov :-D Looks good!

11:09:49 [main] INFO sshj.resume.test2.SlownessTest - 11,161,746.5 KiB transferred in 477.2 seconds (23,389.69 KiB/s)