[jitsi-dev] org.ice4j.ice.Agent createComponent loop


#1

Hi guys,

I'm seeing a lot of "org.ice4j.ice.Agent createComponent" in my logs
i count 32 lines every 10s! (when in a 2 person conf)

it's less than 2 weeks old i think, i will try to bisect it tomorow

I looked at it because the top function according to honest profiler is
BigInteger.montReduce

(t 6,6,s 6,6) java.math.BigInteger.montReduce

(t 5,0,s 3,7) java.math.BigInteger.squareToLen
(t 2,4,s 2,3) java.lang.Object.wait
(t 2,1,s 2,1) java.net.PlainDatagramSocketImpl.send
(t 1,4,s 1,4) java.net.PlainDatagramSocketImpl.receive0
(t 1,9,s 1,3) java.lang.ClassLoader.defineClass1
(t 1,3,s 1,3) java.math.BigInteger.addOne
(t 1,3,s 1,3) java.math.MutableBigInteger.divWord
(t 0,6,s 0,6) java.math.MutableBigInteger.divideOneWord
(t 0,6,s 0,6)
org.jitsi.impl.neomedia.transform.srtp.OpenSSLHMAC.HMAC_Update

an exemple of stack where it appear:

(t 100,0,s 0,0) java.lang.Thread.run

···

  (t 100,0,s 0,0) java.util.concurrent.ThreadPoolExecutor$Worker.run
   (t 100,0,s 0,0) java.util.concurrent.ThreadPoolExecutor.runWorker
    (t 100,0,s 0,0)
org.xmpp.component.AbstractComponent$PacketProcessor.run
     (t 100,0,s 0,0) org.xmpp.component.AbstractComponent.access$100
      (t 100,0,s 0,0)
org.xmpp.component.AbstractComponent.processQueuedPacket
       (t 100,0,s 0,0) org.xmpp.component.AbstractComponent.processIQ
        (t 100,0,s 0,0)
org.xmpp.component.AbstractComponent.processIQRequest
         (t 100,0,s 0,0)
org.jitsi.videobridge.xmpp.ComponentImpl.handleIQGet
          (t 100,0,s 0,0)
org.jitsi.videobridge.xmpp.ComponentImpl.handleIQ
           (t 99,5,s 0,0)
org.jitsi.videobridge.xmpp.ComponentImpl.handleIQ
            (t 99,5,s 0,0)
org.jitsi.videobridge.xmpp.ComponentImpl.handleIQRequest
             (t 99,5,s 0,0)
org.jitsi.videobridge.Videobridge.handleHealthCheckIQ
              (t 99,5,s 0,0) org.jitsi.videobridge.health.Health.check
               (t 98,4,s 0,0) org.jitsi.videobridge.health.Health.check
                (t 74,9,s -0,0)
org.jitsi.videobridge.Content.createRtpChannel
                 (t 51,7,s 0,0)
org.jitsi.videobridge.RtpChannel.initialize
                  (t 51,7,s 0,0) org.jitsi.videobridge.Channel.initialize
                   (t 51,7,s 0,0)
org.jitsi.videobridge.Channel.createTransportManager
                    (t 51,7,s 0,0)
org.jitsi.videobridge.IceUdpTransportManager.<init>
                     (t 50,3,s 0,0)
org.jitsi.impl.neomedia.transform.dtls.DtlsControlImpl.<init>
                      (t 50,1,s 0,0)
org.jitsi.impl.neomedia.transform.dtls.DtlsControlImpl.generateKeyPair
                       (t 50,1,s 0,0)
org.bouncycastle.crypto.generators.RSAKeyPairGenerator.generateKeyPair
                        (t 49,7,s 0,0)
org.bouncycastle.crypto.generators.RSAKeyPairGenerator.chooseRandomPrime
                         (t 48,5,s 0,0) java.math.BigInteger.<init>
                          (t 48,5,s 0,0) java.math.BigInteger.largePrime
                           (t 46,6,s 0,2) java.math.BitSieve.retrieve
                            (t 46,4,s 0,0)
java.math.BigInteger.primeToCertainty
                             (t 40,1,s 0,0)
java.math.BigInteger.passesMillerRabin
                              (t 39,7,s 0,0) java.math.BigInteger.modPow
                               (t 39,7,s 0,7)
java.math.BigInteger.oddModPow
                                (t 22,3,s 22,3)
java.math.BigInteger.montReduce
                                (t 16,7,s 12,3)
java.math.BigInteger.squareToLen


#2

Hey Etienne,

Hi guys,

I'm seeing a lot of "org.ice4j.ice.Agent createComponent" in my logs
i count 32 lines every 10s! (when in a 2 person conf)

it's less than 2 weeks old i think, i will try to bisect it tomorow

We too ran into this and thought it was a problem. It turned out it is a side-effect the recent addition of health-checks from jicofo to the bridge. You can confirm by looking at RECV lines prior to these, you should see something like:
<iq type=“get” to=“jvb1.beta.meet.jit.si” from=“focus@auth.beta.meet.jit.si/focus7690899807136037” id=“rNQxn-72”><healthcheck xmlns=“http://jitsi.org/protocol/healthcheck”/></iq>

Regards,
Boris

I looked at it because the top function according to honest profiler is
BigInteger.montReduce

Hmm, so it appears that the health checks lead to the establishment of a DTLS connection, which may be somewhat expensive. This may be something to consider. Do you have any observations on how much of an effect it has?

Regards,
Boris

···

On 03/03/16 11:18, Etienne Champetier wrote:


#3

Hey Etienne,

Hi guys,

I'm seeing a lot of "org.ice4j.ice.Agent createComponent" in my logs
i count 32 lines every 10s! (when in a 2 person conf)

it's less than 2 weeks old i think, i will try to bisect it tomorow

We too ran into this and thought it was a problem. It turned out it is a

side-effect the recent addition of health-checks from jicofo to the bridge.
You can confirm by looking at RECV lines prior to these, you should see
something like:

<iq type="get" to="jvb1.beta.meet.jit.si" from="

focus@auth.beta.meet.jit.si/focus7690899807136037"
id="rNQxn-72"><healthcheck xmlns="http://jitsi.org/protocol/healthcheck
"/></iq>

Regards,
Boris

I looked at it because the top function according to honest profiler is
BigInteger.montReduce

Hmm, so it appears that the health checks lead to the establishment of a

DTLS connection, which may be somewhat expensive. This may be something to
consider. Do you have any observations on how much of an effect it has?

It's way too expensive, health check consume more than normal operation ...

Also i don't understand why 32 new components for 1 health check?

···

Le 3 mars 2016 20:27, "Boris Grozev" <boris@jitsi.org> a écrit :

On 03/03/16 11:18, Etienne Champetier wrote:

Regards,
Boris

_______________________________________________
dev mailing list
dev@jitsi.org
Unsubscribe instructions and other list options:
http://lists.jitsi.org/mailman/listinfo/dev


#4

>
> Hey Etienne,
>
>>
>> Hi guys,
>>
>> I’m seeing a lot of “org.ice4j.ice.Agent createComponent” in my logs
>> i count 32 lines every 10s! (when in a 2 person conf)
>>
>> it’s less than 2 weeks old i think, i will try to bisect it tomorow
>
> We too ran into this and thought it was a problem. It turned out it
is a side-effect the recent addition of health-checks from jicofo to the
bridge. You can confirm by looking at RECV lines prior to these, you
should see something like:
> <iq type=“get” to=“jvb1.beta.meet.jit.si
<http://jvb1.beta.meet.jit.si>”
from=“focus@auth.beta.meet.jit.si/focus7690899807136037
<http://focus@auth.beta.meet.jit.si/focus7690899807136037>”
id=“rNQxn-72”><healthcheck
xmlns=“http://jitsi.org/protocol/healthcheck”/></iq>
>
> Regards,
> Boris
>
>>
>> I looked at it because the top function according to honest profiler is
>> BigInteger.montReduce
>
> Hmm, so it appears that the health checks lead to the establishment
of a DTLS connection, which may be somewhat expensive. This may be
something to consider. Do you have any observations on how much of an
effect it has?

It's way too expensive, health check consume more than normal operation ...

Yes, we do see a significant increase.

Also i don't understand why 32 new components for 1 health check?

The log message is somewhat misleading, it is printed once for each candidate[0]. The health check creates a new conference, with two audio and two video channels (and no bundle, IIRC, so separate cancidates for each) and connects them together.

Regards,
Boris

[0] https://github.com/jitsi/ice4j/blob/master/src/main/java/org/ice4j/ice/Agent.java#L408

···

On 03/03/16 13:51, Etienne Champetier wrote:

Le 3 mars 2016 20:27, "Boris Grozev" <boris@jitsi.org > <mailto:boris@jitsi.org>> a écrit :
> On 03/03/16 11:18, Etienne Champetier wrote:


#5

>
> Hey Etienne,
>
>
>>
>> Hi guys,
>>
>> I'm seeing a lot of "org.ice4j.ice.Agent createComponent" in my logs
>> i count 32 lines every 10s! (when in a 2 person conf)
>>
>> it's less than 2 weeks old i think, i will try to bisect it tomorow
>
>
> We too ran into this and thought it was a problem. It turned out it
is a side-effect the recent addition of health-checks from jicofo to the
bridge. You can confirm by looking at RECV lines prior to these, you
should see something like:
> <iq type="get" to="jvb1.beta.meet.jit.si
<http://jvb1.beta.meet.jit.si>"
from="focus@auth.beta.meet.jit.si/focus7690899807136037
<http://focus@auth.beta.meet.jit.si/focus7690899807136037>"

id=“rNQxn-72”><healthcheck
xmlns=“http://jitsi.org/protocol/healthcheck”/></iq>
>
>
> Regards,
> Boris
>
>
>>
>> I looked at it because the top function according to honest profiler

is

>> BigInteger.montReduce
>
>
> Hmm, so it appears that the health checks lead to the establishment
of a DTLS connection, which may be somewhat expensive. This may be
something to consider. Do you have any observations on how much of an
effect it has?

It's way too expensive, health check consume more than normal operation

...

Yes, we do see a significant increase.

Also i don't understand why 32 new components for 1 health check?

The log message is somewhat misleading, it is printed once for each

candidate[0]. The health check creates a new conference, with two audio and
two video channels (and no bundle, IIRC, so separate cancidates for each)
and connects them together.

OK so if it's normal behaviour, do we really need a new RSA key so often?
One per server run could be enough?

Regards,
Boris

[0]

https://github.com/jitsi/ice4j/blob/master/src/main/java/org/ice4j/ice/Agent.java#L408

···

Le 3 mars 2016 21:09, "Boris Grozev" <boris@jitsi.org> a écrit :

On 03/03/16 13:51, Etienne Champetier wrote:

Le 3 mars 2016 20:27, "Boris Grozev" <boris@jitsi.org >> <mailto:boris@jitsi.org>> a écrit :
> On 03/03/16 11:18, Etienne Champetier wrote:

_______________________________________________
dev mailing list
dev@jitsi.org
Unsubscribe instructions and other list options:
http://lists.jitsi.org/mailman/listinfo/dev