Log messages not being sent to the server about client-java HOT 20 CLOSED

ok, looks like i've found solution and root cause.

First of all

This is a very synthetic test and there are specifics how JVM process loops as for, each, while, etc..
JVM optimise loop with predictable output, and convert it into the some sort of single line call.

a standard compiler optimization that enables faster loop execution. Loop unrolling increases the loop body size while simultaneously decreasing the number of iterations. Loop unrolling also increases the effectiveness of other optimizations.

Details from here: https://stackoverflow.com/questions/40305266/understanding-loops-performance-in-jvm

Second

I found a direct correlation with rp.batch.size.logs and number of log-lines.
i got it set as 20 by default, and this gave me 5120 log lines.
@sisihi from above got 2560 log lines, and I assume that he got batch size set as 10.

In my experiments, I got

• 20480 log-lines for rp.batch.size.logs=80 (20480/80=256)
• 30720 log-lines for rp.batch.size.logs=120 (30720/120=256)
• 46080 log-lines for rp.batch.size.logs=180 (46080/180=256)

Thus, we see a magic size of 256. 256 objects of Array, which fits batched logs.
Looks like this is a default java limitation for the object type created in loop, or something.
And looks like, @HardNorth, we need to address it in our client-java.

Third

How to get same numbers.
In order to avoid Java loops optimisation, we should move a call of logger to a separate Class and Method. This breaks Java optimisation.
I've made a separate Print.class

package foo;

public class Print{

	public static void printLine(int i, org.slf4j.Logger logger){
		logger.info("Log message #{}", i);
	}
}

and updated LargeLogTest.class accordingly, with a loop of 45000:

package foo;

import org.testng.annotations.Test;
import foo.Print;

@Test
public class LargeLogTest {

	private static final org.slf4j.Logger logger = org.slf4j.LoggerFactory.getLogger(LargeLogTest.class);
	private static final Print print = new Print();

	@Test
	public void logManyLinesUsingSLF4J() {
		for (int i = 0; i < 45000; i++) {
			print.printLine(i, logger);
		}
	}
}

in reportportal.properties I've changed rp.batch.size.logs

rp.batch.size.logs = 180

Since 256*180=46080, it can fit 45000 log-lines easy.
please see archive with the updated code.

reportportal-log-limit-issue.zip

cc @dagansandler @sisihi

from client-java.

OK. I've updated our client and TestNG agent for better logging performance here they are:
https://github.com/reportportal/client-java/releases/tag/5.0.21
https://github.com/reportportal/agent-java-testNG/releases/tag/5.0.11

But I have a lot to say.
@dagansandler @sisihi @ayuryev @DzmitryHumianiuk

First of all, Report Portal Client was designed for functional testing nobody thought it will be used for pushing hundreds of thousands items during seconds or minutes within a launch. And it will not support such performance any time soon. As we discussed internally our current priority is to implement and support as many integrations as possible, rather than making Report Portal a tool for performance and high-load test reports. Performance issues are very expensive to fix.

Second, even with no logs it still possible to knock out RP client by creating thousands of test items per second. To ensure that we uploaded everything on test execution end we use single ExecutorService and await it termination. If the service is overwhelmed with anything, test items will start accumulating inside internal queues. In case of a queue overflow there is an internal exceptions happens and the whole Test or Test Suite won't be reported.

Now with more technical details. Report Portal Client uses rx-java of version 2 under the hood and it has standard setting for internal queue length (128): https://github.com/ReactiveX/RxJava/blob/2.x/src/main/java/io/reactivex/Flowable.java#L156
rx-java works pretty fast and usually it empty this queue in milliseconds but sending anything through internet is a slow process. Request sending overflows internal ExecutorService and then queue, and results in MissingBackpressureException. Log items which managed to pass to the queue will be processed afterward, but new items won't be sent to the queue. That's why log flow stops somewhere at a number which multiple to 250. Because we are reporting tool we don't interfere into test execution and just silently continue processing. Luckily we create a new log processing flowable for every test item, that's why you still able to see logs for different test items even if some of log processors failed.
https://github.com/reportportal/client-java/blob/develop/src/main/java/com/epam/reportportal/service/LoggingContext.java#L148

rx-java has a system property rx2.buffer-size by which you can control internal queue maximum size. Actually rx-java creates many of small queues while operating, io.reactivex.Flowable class has hundreds of references on static method bufferSize() which returns a value set by the property, or default one (128 as was mentioned before). Hence changing this property with higher values may result extensive memory consumption, especially if you put high volume of load on the client. Therefore we decided to introduce a separate property rp.rx.buffer.size which affects only log upload part. Moreover I updated log processing flow in such a way to make it dynamically increase queue size if necessary. But starting with higher property values gives better performance. The drawback of this as was said is higher memory consumption, but I will see how it goes.

I implemented a test, and with these property values I was able to log all 30K entries without any loss:
https://github.com/reportportal/examples-java/blob/too-many-logs-test/example-testng-logback/src/main/resources/reportportal.properties#L8-L9

Here is my crazy test:
https://github.com/reportportal/examples-java/blob/too-many-logs-test/example-testng-logback/src/main/java/com/epam/reportportal/example/testng/logback/TestManyLogs.java

I believe this is the best what can be pulled out of this design. Any further threads with any complains that it is impossible to report hundred of thousands items in a few seconds will be closed with a reference on the current reply.

Thanks.

from client-java.

@sisihi @dagansandler @DzmitryHumianiuk fixed in the latest version
https://bintray.com/epam/reportportal/client-java/4.0.16

from client-java.

Indeed @HardNorth @DzmitryHumianiuk , it took me some time to dive into everything you wrote, but thank you for
the effort of investigating this and the detailed analysis and explanations!

from client-java.

I am seeing this bug again while using the following versions:

        <dependency>
            <groupId>com.epam.reportportal</groupId>
            <artifactId>client-java</artifactId>
            <version>5.0.18</version>
        </dependency>
        <dependency>
            <groupId>com.epam.reportportal</groupId>
            <artifactId>commons-model</artifactId>
            <version>5.3.3</version>
        </dependency>
        <dependency>
            <groupId>com.epam.reportportal</groupId>
            <artifactId>logger-java-log4j</artifactId>
            <version>5.0.3</version>
        </dependency>

Simple test method logging 3000 messages, getting only ~2670 messages reported per method.

from client-java.

Attaching a zipped project.

To reproduce the issue:

1. Extract zip
2. Edit src/test/resources/reportportal.properties with UUID and server address
3. Execute ./gradlew test
4. One test class called LargeLogTest should execute, logging 5000 log messages.
5. Log messages will be printed to console, but only about 2700 will be logged in RP

The zip also contains a copy of the latest docker-compose file so you can easily bring it up and validate the issue against a fresh local instance of RP.

Sample project uses agent-java-testng:5.0.8 and logger-java-log4j:5.0.3, with testng:7.1.0 and loggin using SLF4J and log4j 1.2.17

reportportal-log-limit-issue.zip

from client-java.

Same issue (max 2600 log items) with agent-java-testng:5.0.8, logger-java-log4j:5.0.3, testng:7.1.0, slf4j-log4j12:1.7.30

from client-java.

@HardNorth @DzmitryHumianiuk thanks for your informative answers and approach explaining for RP agents usage 👍

from client-java.

@dagansandler good catch.

team will take a look in next sprints.

from client-java.

Small clarification just in case:
This issue occurs when more than 2560 log items are sent for a specific test item.

from client-java.

Team is focused on 5.0 finalization.
As soon as it will be closed to stabilization, we will take a look into agents

from client-java.

Hello,
I am using cucumber java:

  <dependency>
      <groupId>com.epam.reportportal</groupId>
      <artifactId>agent-java-cucumber</artifactId>
      <version>4.0.2</version>
  </dependency>
  <dependency>
      <groupId>com.epam.reportportal</groupId>
      <artifactId>logger-java-logback</artifactId>
      <version>4.0.0</version>
  </dependency>

Encountered the same "2560" issue as well.
Thanks.

from client-java.

@sisihi @dagansandler guys, could you provide a project that i can use to reproduce the issue ?

from client-java.

@dagansandler it would be nice if you can create a small project code which represent the issue.

@HardNorth @pbortnik is it related to JVM configuration?

from client-java.

@dagansandler which agent do you use?

from client-java.

@DzmitryHumianiuk 3k logs, it's more likely about batch and buffer sizes. But it needs investigation, it might be server processing failures.

from client-java.

@HardNorth I'm using a custom agent (initially based on the TestNG agent), but per @DzmitryHumianiuk's request I was able to reproduce this easily using the vanilla docker-compose.yml latest file and the latest testng agent.

Will share the project soon.

from client-java.

@dagansandler just tried your example on my laptop.
mac os, openjdk 11.0.10 2021-01-19, fresh install of java, all settings are default.

5000 of 5000.

but once i've change it to 15'000
i got just 5120. in 3 attempts.

Then i've added Thread.sleep()

	@Test
	public void logManyLinesUsingSLF4J() {
	for (int i = 0; i < 15000; i++) {
		logger.info("Log message #{}", i);
		try {
			Thread.sleep(1);
		} 
		catch(InterruptedException e){}
	}

it also gave nothing.

from client-java.

from client-java.

@dagansandler
nothing special there. just 5.3.5 version of api.
https://github.com/reportportal/reportportal/blob/d2f22ff3a94c2021e2318679e4dbc495080e52b5/docker-compose.yml

from client-java.