Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Slowness in 0.32.1-SNAPSHOT compared to 0.32.0 release #777

Closed
brenttyler opened this issue Apr 6, 2022 · 6 comments
Closed

Slowness in 0.32.1-SNAPSHOT compared to 0.32.0 release #777

brenttyler opened this issue Apr 6, 2022 · 6 comments

Comments

@brenttyler
Copy link
Contributor

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
Copy link
Contributor

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

@brenttyler
Copy link
Contributor Author

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

@vladimirlagunov
Copy link
Contributor

Well, I'll take a look.

@brenttyler
Copy link
Contributor Author

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 added a commit to vladimirlagunov/sshj that referenced this issue Apr 6, 2022
…oteFile

Due to a bug in logic introduced by hierynomus#769, RemoteFile.ReadAheadRemoteFileInputStream started to send new read ahead requests for file parts that had already been requested.

Every call to read() asked the server to send parts of the file from the point which is already downloaded. Instead, it should have asked to send parts after the last requested part. This commit adds exactly this logic.

The bug didn't cause content corruption. It only affected performance, both on servers and on clients.
vladimirlagunov added a commit to vladimirlagunov/sshj that referenced this issue Apr 6, 2022
…oteFile

Due to a bug in logic introduced by hierynomus#769, RemoteFile.ReadAheadRemoteFileInputStream started to send new read ahead requests for file parts that had already been requested.

Every call to read() asked the server to send parts of the file from the point which is already downloaded. Instead, it should have asked to send parts after the last requested part. This commit adds exactly this logic.

The bug didn't cause content corruption. It only affected performance, both on servers and on clients.
@vladimirlagunov
Copy link
Contributor

@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
Copy link
Contributor Author

brenttyler commented Apr 6, 2022

@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)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants