Possible Problem: 2 BaseChannels using the same serverInLock object

[Jonathan]

Hi,
I was testing my code, wondering why it was taking so long for a
second connection to my server to occur. I found that each client
tries to send a message immediately on making the connection. Both
these ISOServer$Session objects had their own BaseChannel, but each
had the same serverInLock and serverOutLock objects. This is not good.
I suspect it happens because of a clone() method, but I'm still
investigating.

Also, I have noticed that the unit tests in jpos take 12 minutes to
run on my humble laptop. Why should they take so long?

Here's what I see on my machine:
test:
[junit] Running org.jpos.iso.AllTests
[junit] Tests run: 183, Failures: 0, Errors: 0, Time elapsed:
0.338 sec
[junit] Running org.jpos.iso.packagers.PackagerTestCase
[junit] Tests run: 13, Failures: 0, Errors: 0, Time elapsed: 0.766
sec
[junit] Running org.jpos.q2.iso.QMUXTestCase
[junit] Tests run: 3, Failures: 0, Errors: 0, Time elapsed: 12.692
sec
[junit] Running org.jpos.space.JDBMSpaceTestCase
[junit] Tests run: 9, Failures: 0, Errors: 0, Time elapsed:
212.026 sec
[junit] Running org.jpos.space.JESpaceTestCase
[junit] Tests run: 10, Failures: 0, Errors: 0, Time elapsed:
113.193 sec
[junit] Running org.jpos.space.TSpaceTestCase
[junit] Tests run: 13, Failures: 0, Errors: 0, Time elapsed: 4.003
sec
[junit] Running org.jpos.transaction.ContextTestCase
[junit] Tests run: 1, Failures: 0, Errors: 0, Time elapsed: 0.009
sec
[junit] Running org.jpos.transaction.TransactionManagerTestCase
[junit] Tests run: 2, Failures: 0, Errors: 0, Time elapsed:
366.015 sec
[junit] Running org.jpos.util.FSDMsgPropertiesTestCase
[junit] Tests run: 1, Failures: 0, Errors: 0, Time elapsed: 0.016
sec
[junit] Running org.jpos.util.FSDMsgSeparatorTestCase
[junit] Tests run: 1, Failures: 0, Errors: 0, Time elapsed: 0.005
sec
[junit] Running org.jpos.util.FSDMsgTestCase
[junit] Tests run: 9, Failures: 0, Errors: 0, Time elapsed: 0.023
sec
[junit] Running org.jpos.util.ThroughputControlTestCase
[junit] Tests run: 4, Failures: 0, Errors: 0, Time elapsed: 14.302
sec

The TransactionManagerTestCase, JDBMSpaceTestCase and the
JESpaceTestCase take most of the time. Could these be the same problem
I am seeing? Sorry, I haven't looked at what the tests are doing, so I
could be completely wrong.

Ciao,
Jonathan

[Alejandro Revilla]

Good observation on the lock, and yes, that has to be a problem with clone().

If you get to fix it, then great, otherwise we can file an issue with your findings in https://jpos.org/support so we can track it (let me know if you need karma to file bugs there).

As for the test time, there's some code that add plenty of entries to the JDBM and JE spaces, I used those during development not as a unit test but just to do some profiling, I can move them down now (there's a COUNT variable), but anyway, it takes, 1'25" in my iMac which is not fast at all.

[Jonathan]

Alejandro,
just confirmed it. Its definitely BaseChannel.clone() that's wrong.
I'm going to create new lock objects for the clone, and I expect all
is well then.
I will also have a look for any other classes that have lock objects
and clone() methods.

BTW: I want a new machine for christmas! Your iMac is about 8 times
faster than my Acer 5920G. Grrr!
Ciao
Jonathan

[Jonathan]

Alejandro,
it would seem that the clone() method s only called by ISOServer.run
().

That immediately calls clonedChannel.accept(serverSocket) and this
then does a connect, overwriting the serverIn and serverOut data
streams.

I think the clone() operation should not return a BaseChannel with any
opened streams.

If I just clone the locks, or create new lock objects, without cloning
the streams, then other callers of BaseChannel.clone() could find
their code broken, because the stream objects would be synchronized by
2 different locks. Therefore, I propose to null the streams in the
clone. This may cause NPEs or channel not connected errors in their
code, but it should be obvious how to fix it, and I don't think many
people call clone() anyway.

BTW, what should I do about the cnt, the counters array? This is also
cloned, but the counters are not reset.
Ciao,
Jonathan

[Alejandro Revilla]

Are you running off QServer or programmatically?

Isn't the client channel to be cloned a pristine unused (no open streams) channel?

Because if it is not pristine, then there is the problem.

[Alejandro Revilla]

BTW, you using BaseChannel > r2792 ?

I've introduced a change there and we have specific serverInLock and serverOutLock.

Please svn diff -r2791 BaseChannel.java to see them all.

[Jonathan]

Alejandro,
I'm running via Q2. I haven't checked if the streams are open, but I'm
programming defensively. Other users of BaseChannel might be calling
clone() after connecting a channel. My code avoids any problems.

BTW, my server connections are now blazingly fast, so this was
definitely the problem. I also checked for other clone() methods in
the framework, and the only one that should be looked at is
ChannelPool.clone(), as it also clones its pool, and I'm not sure if
it should do so.

Finally, I noticed a small improvement (about 15%) in the running
times of the unit tests, although I would not swear it is my code
that's doing it.
Ciao,
Jonthan

[Jonathan]

Alejandro,
I always do an update before I start changing jPos code. So, I was
actually working on r2793, which contains Mark's further change for
the dynamicPackager code.
Ciao,
Jonathan

[Alejandro Revilla]

Excellent. Those are great news!