Performance of HTTP vs. SSH

[Steffen Gebert]

Hi,

I noticed that Git operations against our Gitblit 1.6.2 are magnitudes faster via SSH than via HTTPS (through Tomcat).

Pulling/Pusing takes only milliseconds instead of > 10 sec. Repository size does not matter.

Is this usual or might there be something wrong/bad in our setup? Not sure, what detail would be helpful for you :)

Best regards
Steffen

[Luca Milanesio]

I would have expected the other way around :-O

Git/SSH is typically slower … unless there is some delay in your reverse proxy.

Luca.

--
You received this message because you are subscribed to the Google Groups "gitblit" group.
To unsubscribe from this group and stop receiving emails from it, send an email to gitblit+u...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Steffen Gebert]

Thanks for your reply, Luca.

Browsing the web interface is blazing fast (except loading the start page for the first time during login). And this is the point, which now comes to my mind: LDAP auth.

I've launched tcpdump and see the following data exchange during login:

12:11:16.953238 IP ldap.389 > gitblit.59987: Flags [P.], seq 17925:18250, ack 1118, win 158, options [nop,nop,TS val 949987834 ecr 949987439], length 325
12:11:16.953368 IP gitblit.59987 > ldap.389: Flags [.], ack 18250, win 932, options [nop,nop,TS val 949987439 ecr 949987834], length 0
12:11:16.953438 IP ldap.389 > gitblit.59987: Flags [P.], seq 18250:18511, ack 1118, win 158, options [nop,nop,TS val 949987835 ecr 949987439], length 261
12:11:16.953620 IP ldap.389 > gitblit.59987: Flags [P.], seq 18511:18852, ack 1118, win 158, options [nop,nop,TS val 949987835 ecr 949987439], length 341
12:11:16.953833 IP ldap.389 > gitblit.59987: Flags [P.], seq 18852:19241, ack 1118, win 158, options [nop,nop,TS val 949987835 ecr 949987439], length 389
12:11:16.954011 IP ldap.389 > gitblit.59987: Flags [P.], seq 19241:19518, ack 1118, win 158, options [nop,nop,TS val 949987835 ecr 949987439], length 277
12:11:16.954142 IP ldap.389 > gitblit.59987: Flags [P.], seq 19518:19699, ack 1118, win 158, options [nop,nop,TS val 949987835 ecr 949987439], length 181
12:11:16.954349 IP ldap.389 > gitblit.59987: Flags [P.], seq 19699:19864, ack 1118, win 158, options [nop,nop,TS val 949987835 ecr 949987439], length 165
12:11:16.954578 IP gitblit.59987 > ldap.389: Flags [.], ack 19864, win 882, options [nop,nop,TS val 949987439 ecr 949987835], length 0
12:11:29.441625 IP gitblit.59987 > ldap.389: Flags [P.], seq 1118:1155, ack 19864, win 1321, options [nop,nop,TS val 949990561 ecr 949987835], length 37
12:11:29.441821 IP gitblit.59987 > ldap.389: Flags [P.], seq 1155:1192, ack 19864, win 1321, options [nop,nop,TS val 949990561 ecr 949987835], length 37
12:11:29.442381 IP ldap.389 > gitblit.59987: Flags [.], ack 1192, win 158, options [nop,nop,TS val 949990957 ecr 949990561], length 0
12:11:29.442854 IP ldap.389 > gitblit.59987: Flags [P.], seq 19864:19965, ack 1192, win 158, options [nop,nop,TS val 949990957 ecr 949990561], length 101
12:11:29.442863 IP ldap.389 > gitblit.59987: Flags [F.], seq 19965, ack 1192, win 158, options [nop,nop,TS val 949990957 ecr 949990561], length 0
12:11:29.443042 IP gitblit.59987 > ldap.389: Flags [P.], seq 1192:1229, ack 19966, win 1321, options [nop,nop,TS val 949990562 ecr 949990957], length 37
12:11:29.443070 IP gitblit.59987 > ldap.389: Flags [F.], seq 1229, ack 19966, win 1321, options [nop,nop,TS val 949990562 ecr 949990957], length 0
12:11:29.443622 IP ldap.389 > gitblit.59987: Flags [R], seq 99145032, win 0, length 0
12:11:29.443637 IP ldap.389 > gitblit.59987: Flags [R], seq 99145032, win 0, length 0

There is the 13sec gap (repeated measurement multiple times). Question is, what is happening in between. As the last packet from gitblit to ldap at 12:11:16 is an ACK only, it's not the LDAP server taking long to respond.

Is that maybe the authentication first and retrieving the groups after the delay?

This might be the reason, why SSH is so much faster, as there is not a single message to the LDAP server.

I hope I might find some time later, to switch gitblit to debug logging and see, what is happening in between. Any pointers and assumptions in the meantime are never the less welcome!

Steffen

[Luca Milanesio]

My bad … I typically use Gitblit for the GUI only and JGit directly (inside Gerrit) for serving the Git protocol :-(

We need James here :-) 

Luca.

[James Moger]

There isn't much useful logging in Gitblit's LDAP auth provider.  The underlying LDAP client library (unboundid) may be able to display more detailed information (https://docs.ldap.com/ldap-sdk/docs/getting-started/debug.html).

If you startup Gitblit with some -D VM args then you should be able to enable this:

-Dcom.unboundid.ldap.sdk.debug.enabled=true
-Dcom.unboundid.ldap.sdk.debug.level=INFO

You'll have to play with the log levels.
"ALL", "SEVERE", "WARNING", "INFO", "CONFIG", "FINE", "FINER", "FINEST", or "OFF".

-J

[Steffen Gebert]

Thanks, James!

Do you have in mind, how I can supply this with Tomcat (under Debian Linux)?

I already tried exporting CATALINA_OPTS and JAVA_OPTS as well as modified these in /usr/share/tomcat7/bin/catalina.sh without anything appearing in the log.

Thanks
Steffen

[Steffen Gebert]

the log == catalina.out

[James Moger]

JAVA_OPTS would've been my guess.  Perhaps you successfully set them and it's not working.  Did you inspect your process with VisualVM or JConsole?

-J

[Steffen Gebert]

Hi James,

no, I'm not a Java pro. Haven't used them, but will try the next days.

Yours
Steffen

> You received this message because you are subscribed to a topic in the Google Groups "gitblit" group.
> To unsubscribe from this topic, visit https://groups.google.com/d/topic/gitblit/eEGZpiApDTQ/unsubscribe.
> To unsubscribe from this group and all its topics, send an email to gitblit+u...@googlegroups.com.

[Steffen Gebert]

Hi,

while searching for how to connect VisualVM to Tomcat, I found this article and that I have to specify environment variables in /usr/share/tomcat7/bin/setenv.sh.

Now I see this in the log:

Jan 30, 2015 9:49:51 AM com.unboundid.util.Debug debugLDAPResult
INFO: level="INFO" threadID=43 threadName="Connection reader for connection to ldap:389" revision=10784 connectionID=2 connectedTo="ldap:389" readLDAPResult="SearchResultEntry(dn='cn=example-group,ou=groups,dc=example,dc=org', messageID=5, attributes={Attribute(name=cn, values={'example-group'})}, controls={})"
Jan 30, 2015 9:49:51 AM com.unboundid.util.Debug debugLDAPResult
INFO: level="INFO" threadID=43 threadName="Connection reader for connection to ldap:389" revision=10784 connectionID=2 connectedTo="ldap:389" readLDAPResult="SearchResult(resultCode=0 (success), messageID=5, entriesReturned=-1, referencesReturned=-1)"
Jan 30, 2015 9:50:03 AM com.unboundid.util.Debug debug
INFO: level="INFO" threadID=29 threadName="http-bio-8080-exec-1" revision=10784 message="Sending LDAP unbind request."
Jan 30, 2015 9:50:03 AM com.unboundid.util.Debug debugASN1Write
INFO: level="INFO" threadID=29 threadName="http-bio-8080-exec-1" revision=10784 writingASN1Element="30050201064200"
Jan 30, 2015 9:50:03 AM com.unboundid.util.Debug debugDisconnect
INFO: level="INFO" threadID=43 threadName="Connection reader for connection to ldap:389 (closed)" revision=10784 connectionID=2 disconnectedFrom="ldap:389" disconnectType="UNBIND"
Jan 30, 2015 9:50:03 AM com.unboundid.util.Debug debugDisconnect
INFO: level="INFO" threadID=29 threadName="http-bio-8080-exec-1" revision=10784 connectionID=2 disconnectedFrom="ldap:389" disconnectType="UNBIND"
2015-01-30 09:50:03 [INFO ] 77 repository models loaded for steffen.gebert in 92 msecs

The groups are loaded quickly, the question is, what happens until the UNBIND..

Will try to figure that out with VisualVM.

Thanks
Steffen

> To unsubscribe from this group and stop receiving emails from it, send an email to gitblit+unsubscribe@googlegroups.com.

> For more options, visit https://groups.google.com/d/optout.
>
>
> --
> You received this message because you are subscribed to a topic in the Google Groups "gitblit" group.
> To unsubscribe from this topic, visit https://groups.google.com/d/topic/gitblit/eEGZpiApDTQ/unsubscribe.

> To unsubscribe from this group and all its topics, send an email to gitblit+unsubscribe@googlegroups.com.

[Steffen Gebert]

This article: http://blog.markshead.com/1129/connecting-visual-vm-to-tomcat-7/

early morning..

[Steffen Gebert]

Hi,

attached is a threaddump taken during the waiting period.

Can anyone interpret this for me?
RUNNABLE means the thread isn't busy, isn't it?

Thanks
Steffen

[Steffen Gebert]

Hey,

anybody willing to interpret this?

 "Connection reader for connection to ldap:389" - Thread t@46
    java.lang.Thread.State: RUNNABLE
         at java.net.SocketInputStream.socketRead0(Native Method)
         at java.net.SocketInputStream.read(SocketInputStream.java:152)
         at java.net.SocketInputStream.read(SocketInputStream.java:122)
         at sun.security.ssl.InputRecord.readFully(InputRecord.java:442)
         at sun.security.ssl.InputRecord.read(InputRecord.java:480)
         at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:927)
         - locked <2126d99a> (a java.lang.Object)
         at sun.security.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:884)
         at sun.security.ssl.AppInputStream.read(AppInputStream.java:102)
         - locked <df81565> (a sun.security.ssl.AppInputStream)
         at java.io.BufferedInputStream.fill(BufferedInputStream.java:235)
         at java.io.BufferedInputStream.read(BufferedInputStream.java:254)
         - locked <fa969f4> (a java.io.BufferedInputStream)
         at com.unboundid.asn1.ASN1StreamReader.read(ASN1StreamReader.java:911)
         at com.unboundid.asn1.ASN1StreamReader.readType(ASN1StreamReader.java:300)
         at com.unboundid.asn1.ASN1StreamReader.beginSequence(ASN1StreamReader.java:848)
         at com.unboundid.ldap.protocol.LDAPMessage.readLDAPResponseFrom(LDAPMessage.java:981)
         at com.unboundid.ldap.sdk.LDAPConnectionReader.run(LDAPConnectionReader.java:254)

    Locked ownable synchronizers:
         - None

Any way to further debug this?

Thanks
Steffen

[Luca Milanesio]

Can you try to do the same using LDAP on 389? (disabling SSL)

Luca.

INFO: level="INFO" threadID=29 threadName="http-bio-8080-exec-1" revision=10784message="Sending LDAP unbind request."


Jan 30, 2015 9:50:03 AM com.unboundid.util.Debug debugASN1Write


INFO: level="INFO" threadID=29 threadName="http-bio-8080-exec-1" revision=10784writingASN1Element="30050201064200"


Jan 30, 2015 9:50:03 AM com.unboundid.util.Debug debugDisconnect
INFO: level="INFO" threadID=43 threadName="Connection reader for connection to ldap:389 (closed)" revision=10784 connectionID=2 disconnectedFrom="ldap:389" disconnectType="UNBIND"
Jan 30, 2015 9:50:03 AM com.unboundid.util.Debug debugDisconnect


INFO: level="INFO" threadID=29 threadName="http-bio-8080-exec-1" revision=10784connectionID=2 disconnectedFrom="ldap:389" disconnectType="UNBIND"

[Steffen Gebert]

Hi Luca,

unfortunately (or fortunately :-)) the LDAP server accepts only STARTTLS connections.

I might have to try that with some test installations..

Steffen

...

[Luca Milanesio]

Hi Steffen,

apologies, this is what I meant (implicitly).

Just to see if we have to rule out SSL or not out of the equation … never meant to say “go without SSL in prod” :-)

Luca.

[Johann Ollivier Lapeyre]

Hi,

We are experiencing here the same LDAP issues (without TLS) with ldap (and only with Gitblit).

I saw that in build.moxie:

com.unboundid:unboundid-ldapsdk:2.3.0

Which is pretty old, and according the unbound's changelog ( https://docs.ldap.com/ldap-sdk/docs/release-notes.html ), many bugfix could be related. 

Johann Ollivier-Lapeyre

[James Moger]

Try updating that dependency and see if that helps?

-J

[Steffen Gebert]

Hi,

"good" to read that we're not the only ones (but also that it's not caused by TLS).

I've created a build using unboundid-ldapsdk-2.3.8.jar and that unfortunately does not change anything :-(

Steffen

[Johann Ollivier Lapeyre]

Hi,

"I've created a build using unboundid-ldapsdk-2.3.8.jar and that unfortunately does not change anything :-("

Same for me. :(

Then, i made a setup of Gitblit / Eclipse, made the LDAP config in gitblit.properties, and succeded to reproduce on debug mode:

In LdapAuthProvider class, load user properties from LDAP seems done quickly, but this part is taking ages:

if (!supportsTeamMembershipChanges()) {

for (TeamModel userTeam : user.teams) {

updateTeam(userTeam);

}

}

I don't think i can go deeper with my knowlage of Gitblit. :/

Johann

[Johann Ollivier Lapeyre]

Some interesting progress:

updateUser is affected too, and it's seem to be related to the user.conf size. And this one can be big if "realm.ldap.synchronize" was set to "true" in the past.

Maybe a file is not efficient enought when there are many potential user (1300 here) or Teams (sqllite or something else?). 

If i clear this file, i get back acceptable login time (< 1s). 

James, do we create a ticket now?

Johann

[James Moger]

I'm more interested in pull requests than todo list items.  I'm getting slow & backed-up.  :)

Having said that, Gitblit has always done something pretty dumb which is likely to be the source of your problem: it rewrites users.conf too often.  The frequency of writes could be reduced if it was smarter at detecting model changes:

https://github.com/gitblit/gitblit/blob/master/src/main/java/com/gitblit/auth/AuthenticationProvider.java#L80
https://github.com/gitblit/gitblit/blob/master/src/main/java/com/gitblit/auth/AuthenticationProvider.java#L92

I don't think it's necessary to introduce a DB just yet - but SQLite would be a strong contender and almost for sure my first choice if that were to happen.

-J

[Johann Ollivier Lapeyre]

 

I'm more interested in pull requests than todo list items.  I'm getting slow & backed-up.  :)

Can't trust you ;)

Having said that, Gitblit has always done something pretty dumb which is likely to be the source of your problem: it rewrites users.conf too often.  The frequency of writes could be reduced if it was smarter at detecting model changes:

https://github.com/gitblit/gitblit/blob/master/src/main/java/com/gitblit/auth/AuthenticationProvider.java#L80
https://github.com/gitblit/gitblit/blob/master/src/main/java/com/gitblit/auth/AuthenticationProvider.java#L92

Nice pointer! With a collegue and friend much more java talented than me, we made some tries... 

And he is trying his first pool request ;)

 

[Johann Ollivier Lapeyre]

Just for the readers and Steffen, the fix (11s going down to less than 2s) was merged by James, so we just have to wait the next release ;)

[Tamas Papp]

On 03/09/2015 10:04 AM, Johann Ollivier Lapeyre wrote:
>
>
> Just for the readers and Steffen, the fix (11s going down to less than
> 2s) was merged by James, so we just have to wait the next release ;)

I've been using develop branch for a very long time and it's quite stable.
IMO it's not worth waiting for the release.

In very rare cases when I saw an issue it was usually easy to revert
back to previous version. It could be problematic, only if there are
serious configuration changles, like in LDAP authentication etc.
However. the recent version uses an included master config file, so the
actual user defined config file is even smaller an easier to maintain.


tamas

[Steffen Gebert]

> Just for the readers and Steffen, the fix (11s going down to less than 2s) was merged by James, so we just have to wait the next release ;)

nice job, thanks!

It's now really fast after deploying from the development branch.

Steffen