Hi Bela
I think I found why you weren't seeing the warnings. The
bench-log4j.xml in github master is configured to log only to the log
file (benchmark.log). If you add an <appender-ref ref="CONSOLE"/>
you'll see the warnings on the console as well.
I am now able to reproduce it pretty reliably, even from IntelliJ. I
created a run configuration for the Transactional class, I set the
module to infinispan-5.1-SNAPSHOT, and I added these JVM arguments:
-Dbench.loops=3000 -Dbench.writerThreads=33 -Dbench.readerThreads=10
-Dbench.dist=true -Dbench.transactional=true -Dbench.numkeys=500
-Dbench.payloadsize=10240 -Dbench.nodes=12 -Djava.net.preferIPv4Stack
-Dlog4j.configuration=bench-log4j.xml
In Sanne's thread dump it was a ClusteredGetCommand that was waiting
for a physical address, but in my test runs it's usually a JOIN that's
failing. And it seems that it happens because we got a discovery
response from 3 nodes (that is our initial num_initial_members), but
none of them was the coordinator:
2012-02-02 08:04:41,672 TRACE [org.jgroups.protocols.PING] (main)
discovery took 8 ms: responses: 3 total (2 servers (0 coord), 1
clients)
2012-02-02 08:04:41,672 TRACE [org.jgroups.protocols.pbcast.GMS]
(main) localhost-47135: initial_mbrs are localhost-36539
localhost-30921
2012-02-02 08:04:41,672 DEBUG [org.jgroups.protocols.pbcast.GMS]
(main) election results: {localhost-32436=2}
2012-02-02 08:04:41,672 DEBUG [org.jgroups.protocols.pbcast.GMS]
(main) sending JOIN(localhost-47135) to localhost-32436
2012-02-02 08:04:41,673 TRACE [org.jgroups.protocols.UNICAST2] (main)
localhost-47135: created connection to localhost-32436 (conn_id=0)
2012-02-02 08:04:41,673 TRACE [org.jgroups.protocols.UNICAST2] (main)
localhost-47135 --> DATA(localhost-32436: #1, conn_id=0, first)
2012-02-02 08:04:41,673 TRACE [org.jgroups.protocols.UDP] (main)
sending msg to localhost-32436, src=localhost-47135, headers are GMS:
GmsHeader[JOIN_REQ]: mbr=localhost-47135, UNICAST2: DATA, seqno=1,
first, UDP: [channel_name=ISPN]
2012-02-02 08:04:41,673 WARN [org.jgroups.protocols.UDP] (main)
localhost-47135: no physical address for localhost-32436, dropping
message
Cheers
Dan
On Wed, Feb 1, 2012 at 7:12 PM, Sanne Grinovero <sanne(a)infinispan.org> wrote:
On 1 February 2012 16:40, Bela Ban <bban(a)redhat.com> wrote:
> Your benchmark is giving me the creeps !
Manik was the original author, I've only been adapting it slightly to
identify performance issues. I wouldn't have used Maven either, but
it's serving me well especially since it turns out I have to
frequently change JGroups version ;-)
> First, which version of JGroups / Infinispan does this use ? Second, is
> there a way to start this in an IDE rather than through maven ? Third, I
> don't think bench-jgroups.xml is picked up at all ! How do I make a change
> to bench-jgroups.xml and have Transactional *use* it ?
1) The intention is to compare Infinispan versions, and see how we
make progress, so the JGroups version is defined as each different
Infinispan version was released with, or in case of a SNAPSHOT the
version it's currently using.
So, assuming you have a fresh snapshot of Infinispan 5.1.0-SNAPSHOT,
it's JGroups 3.0.4.Final
2) As I pointed out in the previous mail, I've reconfigured it for you
to not pick up the bench-jgroups.xml but go with Infinispan's default
UDP configuration.
You have to comment line 15 of bench.sh to use the bench-jgroups.xml,
but then I can't reproduce the issue anymore.
> This maven crap hides so much, I never know what's going on under the covers
> !@$@ Do I have to do mvn install or mvn package when I make a change to
> bench-jgroups.xml ?
Aren't you using bench.sh as I pointed out in the script in my
previous mail? It does mvn install before running it.
But it's also configured to NOT use bench-jgroups.xml, but rather
jgroups-udp.xml.
> I don't think I'll ever switch to this f*cking piece of shit !
I don't think Maven is to be blamed today! What's wrong?
Anyway one of the nice things of this little benchmark is exactly that
it it's a single class with a main file, so you can just import it in
you IDE and run. Any IDE will pick the correct dependencies, thanks to
Maven. Just that if you do, it will use the default test properties as
hardcoded in the test class org.infinispan.benchmark.Transactional:
please set the same environment variable as bench.sh does, unless you
don't want to run my same configuration.
Just ping me for any doubt.
Cheers,
Sanne
>
> Please ping when as soon as you've calmed down... :-)
> Cheers,
>
>
>
>
> On 2/1/12 4:52 PM, Sanne Grinovero wrote:
>>
>> On 1 February 2012 15:18, Bela Ban<bban(a)redhat.com> wrote:
>>>
>>>
>>>
>>> On 2/1/12 10:25 AM, Dan Berindei wrote:
>>>
>>>>> That's not the way it works; at startup of F, it sends its IP
address
>>>>> with the discovery request. Everybody returns its IP address with
the
>>>>> discovery response, so even though we have F only talking to A (the
>>>>> coordinator) initially, F will also know the IP addresses of A,B,C,D
>>>>> and E.
>>>>>
>>>>
>>>> Ok, I stand corrected... since we start all the nodes on the same
>>>> thread, each of them should reply to the discovery request of the next
>>>> nodes.
>>>
>>>
>>>
>>> Hmm, can you reproduce this every time ? If so, can you send me the
>>> program so I can run it here ?
>>>
>>>
>>>> However, num_initial_members was set to 3 (the Infinispan default).
>>>> Could that make PING not wait for all the responses? If it's like
>>>> that, then I suggest we set a (much) higher num_initial_members and a
>>>> lower timeout in the default configuration.
>>>
>>>
>>>
>>> Yes, the discovery could return quickly, but the responses would even be
>>> processed if they were received later, so I don't think that's the
issue.
>>>
>>> The initial discovery should discover *all* IP addresses, later
>>> triggering a discovery because an IP address wasn't found should always
>>> be the exceptional case !
>>>
>>> If you start members in turn, then they should easily form a cluster and
>>> not even merge. Here's what can happen on a merge:
>>> - The view is A|1={A,B}, both A and B have IP addresses for A and B
>>> - The view splits into A|2={A} and B|2={B}
>>> - A now marks B's IP address as removable and B marks A's IP address
as
>>> removable
>>> - If the cache grows to over 500 entries
>>> (TP.logical_addr_cache_max_size) or TP.logical_addr_cache_expiration
>>> milliseconds elapse (whichever comes first), the entries marked as
>>> removable are removed
>>> - If, *before that* the merge view A|3={A,B} is installed, A unmarks B
>>> and B unmarks A, so the entries won't get removed
>>>
>>> So a hypothesis of how those IP addresses get removed could be that the
>>> cluster had a couple of merges, that didn't heal for 2 minutes (?) hard
>>> to believe though...
>>>
>>> We have to get to the bottom of this, so it would be great if you had a
>>> program that reproduced this, that I could send myself. The main
>>> question is why the IP address for the target is gone and/or why the IP
>>> address wasn't received in the first place.
>>>
>>> In any case, replacing MERGE2 with MERGE3 might help a bit, as MERGE3
>>> [1] periodically broadcasts IP address/logical name and logical address:
>>> "An INFO message carries the logical name and physical address of a
>>> member. Compared to MERGE2, this allows us to immediately send messages
>>> to newly merged members, and not have to solicit this information first.
>>> " (copied from the documentation)
>>>
>>>
>>>
>>>>>> Â Note that everything is blocked at this point, we
>>>>>>
>>>>>> won't send another message in the entire cluster until we got
the
>>>>>> physical address.
>>>
>>>
>>>
>>> Understood. Let me see if I can block sending of the message for a max
>>> time (say 2 seconds) until I get the IP address. Not very nice, and I
>>> prefer a different approach (plus we need to see why this happens in the
>>> first place anyway)...
>>>
>>>
>>>>> As I said; this is an exceptional case, probably caused by Sanne
>>>>> starting 12 channels inside the same JVM, at the same time,
therefore
>>>>> causing a traffic spike, which results in dropped discovery requests
or
>>>>> responses.
>>>>>
>>>>
>>>> Bela, we create the caches on a single thread, so we never have more
>>>> than one node joining at the same time.
>>>> At most we could have some extra activity if one node can't join the
>>>> existing cluster and starts a separate partition, but hardly enough to
>>>> cause congestion.
>>>
>>>
>>>
>>> Hmm, does indeed not sound like an issue...
>>>
>>>
>>>>> After than, when F wants to talk to C, it asks the cluster for
C's IP
>>>>> address, and that should be a few ms at most.
>>>>>
>>>>
>>>> Ok, so when F wanted to send the ClusteredGetCommand request to C,
>>>> PING got the physical address right away. But the ClusteredGetCommand
>>>> had to wait for STABLE to kick in and for C to ask for retransmission
>>>> (because we didn't send any other messages).
>>>
>>>
>>>
>>> Yep. Before I implement some blocking until we have the IP address, or a
>>> timeout elapses, I'd like to try to get to the bottom of this problem
>>> first !
>>>
>>>
>>>> Maybe *we* should use RSVP for our ClusteredGetCommands, since those
>>>> can never block... Actually, we don't want to retransmit the request
>>>> if we already got a response from another node, so it would be best if
>>>> we could ask for retransmission of a particular request explicitly ;-)
>>>
>>>
>>>
>>> I'd rather implement the blocking approach above ! :-)
>>>
>>>
>>>> I wonder if we could also decrease desired_avg_gossip and
>>>> stability_delay in STABLE. After all, an extra STABLE round can't
slow
>>>> us when we're not doing anything, and when we are busy we're
going to
>>>> hit the max_bytes limit much sooner than the desired_avg_gossip time
>>>> limit anyway.
>>>
>>>
>>>
>>> I don't think this is a good idea as it will generate more traffic. The
>>> stable task is not skipped when we have a lot of traffic, so this will
>>> compound the issue.
>>>
>>>
>>>>>> I'm also not sure what to make of these lines:
>>>>>>
>>>>>>>>> [org.jgroups.protocols.UDP] sanne-55119: no physical
address for
>>>>>>>>> sanne-53650, dropping message
>>>>>>>>> [org.jgroups.protocols.pbcast.GMS] JOIN(sanne-55119)
sent to
>>>>>>>>> sanne-53650 timed out (after 3000 ms), retrying
>>>>>>
>>>>>>
>>>>>> It appears that sanne-55119 knows the logical name of
sanne-53650, and
>>>>>> the fact that it's coordinator, but not its physical
address.
>>>>>> Shouldn't all of this information have arrived at the same
time?
>>>>>
>>>>>
>>>>> Hmm, correct. However, the logical names are kept in (a static)
>>>>> UUID.cache and the IP addresses in TP.logical_addr_cache.
>>>>>
>>>>
>>>> Ah, so if we have 12 nodes in the same VM they automatically know each
>>>> other's logical name - they don't need PING at all!
>>>
>>>
>>>
>>> Yes. Note that logical names are not the problem; even if we evict some
>>> logical name from the cache (and we do this only for removed members),
>>> JGroups will still work as it only needs UUIDs and IP addresses.
>>>
>>>
>>>> Does the logical cache get cleared on channel stop? I think that would
>>>> explain another weird thing I was seeing in the test suite logs,
>>>> sometimes everyone in a cluster would suddenly forget everyone
else's
>>>> logical name and start logging UUIDs.
>>>
>>>
>>>
>>> On a view change, we remove all entries which are *not* in the new view.
>>> However, 'removing' is again simply marking those members as
>>> 'removable', and only if the cache grows beyond 500
>>> (-Djgroups.uuid_cache.max_entries=500) entries will all entries older
>>> than 5 seconds (-Djgroups.uuid_cache.max_age=5000) be removed. (There is
>>> no separate reaper task running for this).
>>>
>>> So, yes, this can happen, but on the next discovery round, we'll have
>>> the correct values. Again, as I said, UUID.cache is not as important as
>>> TP.logical_addr_cache.
>>>
>>>
>>>> This is running the Transactional benchmark, so it would be simpler if
>>>> we enabled PING trace in the configuration and disabled it before the
>>>> actual benchmark starts. I'm going to try it myself :)
>>>
>>>
>>>
>>> How do you run 12 instances ? Did you change something in the config ?
>>> I'd be interested in trying the *exact* same config you're running,
to
>>> see what's going on !
>>
>>
>> Pushed it for you, committing the exact configuration changes as well:
>>
>> git clone
git://github.com/Sanne/InfinispanStartupBenchmark.git
>> cd InfinispanStartupBenchmark
>> git co my
>> sh bench.sh
>>
>> If you look into bench.sh
>> (as it is at
>>
https://github.com/Sanne/InfinispanStartupBenchmark/blob/my/bench.sh
>> )
>> the lines 9, 15, 28 should be the most interesting.
>>
>> You need to run with Infinispan's default configuration to reproduce the
>> issue,
>> but I wouldn't mind you commenting on
>>
>>
https://github.com/Sanne/InfinispanStartupBenchmark/blob/my/benchmark/src...
>> as well. That's what I'm now using as default for further performance
>> tests.
>>
>> Cheers,
>> Sanne
>>
>>>
>>>
>>> [1]
http://www.jgroups.org/manual-3.x/html/protlist.html#MERGE3
>>>
>>> --
>>> Bela Ban
>>> Lead JGroups (
http://www.jgroups.org)
>>> JBoss / Red Hat
>>> _______________________________________________
>>> infinispan-dev mailing list
>>> infinispan-dev(a)lists.jboss.org
>>>
https://lists.jboss.org/mailman/listinfo/infinispan-dev
>
>
> --
> Bela Ban
> Lead JGroups (
http://www.jgroups.org)
> JBoss / Red Hat
_______________________________________________
infinispan-dev mailing list
infinispan-dev(a)lists.jboss.org
https://lists.jboss.org/mailman/listinfo/infinispan-dev