Ticket #106 (closed defect)

Opened 8 years ago

Last modified 7 years ago

high cpu usage during SFTP copying (nonblock mode)

Reported by: mera-nn Owned by: bagder
Priority: normal Milestone:
Component: SFTP Version:
Keywords: Cc: mera-nn, bagder, poulserge
Blocked By: Blocks:

Description

Using test sftp copying binary , high cpu usage observed. Seems curl uses nonblock mode so sftp usage using curl library is high. Originally issue observed using curl library.

The logs below:

Using latest libssh2

[root@localhost simple]# pwd
/root/libssh2-1.1/example/simple

[root@localhost simple]#./sftp_write 192.168.35.75 user pass test.sftp /tmp/test.block
Fingerprint: 11 12 A1 54 1C 8D 65 40 DD 45 EC F9 12 25 A0 59
libssh2_sftp_init()!
libssh2_sftp_open()!
libssh2_sftp_open() is done, now send data!
all done

cpu usage is OK:

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND

2611 root 15 0 4808 1544 1264 S 11.7 0.1 0:01.48 lt-sftp_write

[root@localhost simple]# ./sftp_write_nonblock 192.168.35.75 user pass test.sftp /tmp/test.nonblock
Fingerprint: 11 12 A1 54 1C 8D 65 40 DD 45 EC F9 12 25 A0 59
libssh2_sftp_init()!
libssh2_sftp_open()!
libssh2_sftp_open() is done, now send data!
all done

High cpu usage !!!

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
2561 root 25 0 4804 1464 1244 R 99.3 0.1 0:09.71 lt-sftp_write_non_block

RedHat? Enterprise Linux Server 5.1. But, I tested this scenario on 3 platforms. Same effect.
So, I think won't be a big problem to reproduce this issue on any Linux platform.

Please, confirm.

Change History

comment:1 Changed 8 years ago by bagder

Thanks, can you try again with the most recent git code and see if you still experience this problem? I've tried to go over the code and cleaned up dubious code and it might just have fixed this. Not to mention that we released 1.2 after the version this is reported against.

comment:2 Changed 8 years ago by anonymous

I have tried latest version of libssh2. same effect . high cpu usage.

comment:3 Changed 8 years ago by bagder

Have you tried to pinpoint what the problem is? Like running strace on the process to see what it does?

comment:4 Changed 8 years ago by poulserge

"strace" output shows the following:
. . .
recv(4, 0x974d890, 16384, MSG_NOSIGNAL) = -1 EAGAIN (Resource temporarily unavailable)
recv(4, 0x974d890, 16384, MSG_NOSIGNAL) = -1 EAGAIN (Resource temporarily unavailable)
recv(4, 0x974d890, 16384, MSG_NOSIGNAL) = -1 EAGAIN (Resource temporarily unavailable)
recv(4, 0x974d890, 16384, MSG_NOSIGNAL) = -1 EAGAIN (Resource temporarily unavailable)
recv(4, 0x974d890, 16384, MSG_NOSIGNAL) = -1 EAGAIN (Resource temporarily unavailable)
recv(4, 0x974d890, 16384, MSG_NOSIGNAL) = -1 EAGAIN (Resource temporarily unavailable)
recv(4, 0x974d890, 16384, MSG_NOSIGNAL) = -1 EAGAIN (Resource temporarily unavailable)
recv(4, 0x974d890, 16384, MSG_NOSIGNAL) = -1 EAGAIN (Resource temporarily unavailable)
recv(4, 0x974d890, 16384, MSG_NOSIGNAL) = -1 EAGAIN (Resource temporarily unavailable)
recv(4, 0x974d890, 16384, MSG_NOSIGNAL) = -1 EAGAIN (Resource temporarily unavailable)
recv(4, 0x974d890, 16384, MSG_NOSIGNAL) = -1 EAGAIN (Resource temporarily unavailable)
recv(4, 0x974d890, 16384, MSG_NOSIGNAL) = -1 EAGAIN (Resource temporarily unavailable)
recv(4, "\340\272\250\265\367C\7\337\340\03557\224\232\377gK\364\207\36\"\306W\v\t\37\3013\262?\5\206\256"..., 16384, MSG_NOSIGNAL) = 68
recv(4, 0x974d890, 16384, MSG_NOSIGNAL) = -1 EAGAIN (Resource temporarily unavailable)
recv(4, 0x974d890, 16384, MSG_NOSIGNAL) = -1 EAGAIN (Resource temporarily unavailable)
recv(4, 0x974d890, 16384, MSG_NOSIGNAL) = -1 EAGAIN (Resource temporarily unavailable)
send(4, "_\227\365\301s\230Gqn\3469\374\334}\25]N\204\3!\226%D\32{\233$\367(\304\324\247"..., 68, MSG_NOSIGNAL) = 68
recv(4, 0x974d890, 16384, MSG_NOSIGNAL) = -1 EAGAIN (Resource temporarily unavailable)
recv(4, 0x974d890, 16384, MSG_NOSIGNAL) = -1 EAGAIN (Resource temporarily unavailable)
recv(4, 0x974d890, 16384, MSG_NOSIGNAL) = -1 EAGAIN (Resource temporarily unavailable)
recv(4, 0x974d890, 16384, MSG_NOSIGNAL) = -1 EAGAIN (Resource temporarily unavailable)
recv(4, 0x974d890, 16384, MSG_NOSIGNAL) = -1 EAGAIN (Resource temporarily unavailable)
recv(4, "\20k\243\224B\327>w\246\377\302\347\341\37\237-\264\202$\4\335\7D\272\22z\177+c\3031\0277"..., 16384, MSG_NOSIGNAL) = 68
recv(4, 0x974d890, 16384, MSG_NOSIGNAL) = -1 EAGAIN (Resource temporarily unavailable)
recv(4, 0x974d890, 16384, MSG_NOSIGNAL) = -1 EAGAIN (Resource temporarily unavailable)
read(3, "Z\0\327\214\1\0\0\1\214\327\352b\1\0\0\1b\352l\3\f\3\22-\360\0\0\0\1\0\0\0018"..., 4096) = 4096
recv(4, 0x974d890, 16384, MSG_NOSIGNAL) = -1 EAGAIN (Resource temporarily unavailable)
send(4, "\217\7g@\16\226\0330\365\334,\256(J\233O\7\370l(\21_\356NI3\311\304\n@\254\36\362"..., 1092, MSG_NOSIGNAL) = 1092
recv(4, 0x974d890, 16384, MSG_NOSIGNAL) = -1 EAGAIN (Resource temporarily unavailable)
recv(4, 0x974d890, 16384, MSG_NOSIGNAL) = -1 EAGAIN (Resource temporarily unavailable)
recv(4, 0x974d890, 16384, MSG_NOSIGNAL) = -1 EAGAIN (Resource temporarily unavailable)
recv(4, 0x974d890, 16384, MSG_NOSIGNAL) = -1 EAGAIN (Resource temporarily unavailable)
recv(4, 0x974d890, 16384, MSG_NOSIGNAL) = -1 EAGAIN (Resource temporarily unavailable)
recv(4, 0x974d890, 16384, MSG_NOSIGNAL) = -1 EAGAIN (Resource temporarily unavailable)
recv(4, 0x974d890, 16384, MSG_NOSIGNAL) = -1 EAGAIN (Resource temporarily unavailable)
. . .

comment:5 Changed 8 years ago by bagder

Can you research further and figure out why this EAGAIN doesn't end up in the loop in libssh2_sftp_read() waiting for the socket to become readable again? The idea is that the recv() function when called from transport.c should basically be pushed back all the way to the libssh2 entry-function and there it should select() until the socket is again signaled to be ready to get read from.

Also, it could be an idea to try this with the git version of libssh2 as I've tried to clean up error code treatment and I might then have changed behavior from what you get with 1.2.

comment:6 Changed 7 years ago by bagder

Is this still a problem with the latest git version?

comment:7 Changed 7 years ago by sf-robot

This Tracker item was closed automatically by the system. It was
previously set to a Pending status, and the original submitter
did not respond within 14 days (the time period specified by
the administrator of this Tracker).

Note: See TracTickets for help on using tickets.