You are viewing a plain text version of this content. The canonical link for it is here.
Posted to log4j-user@logging.apache.org by Pooja Pandey <Po...@asg.com.INVALID> on 2022/03/24 23:06:34 UTC
Synchronization issue in multithreading (Losing huge data in multithreading) with log4j 1.x bridge (2.17.2)
Hi,
In our application we have migrated from log4j1.x to log4j1.x bridge. With Log4j1.x there was no issue with multithreading but with log4j 1.x bridge we have noticed that in multithreading environment there is a huge data loss while logging, however single thread works fine. I see that in Category.java which Logger extends; many methods are not synchronized any more in log4j1.x bridge however which were in case of log4j1.x. I suspect this could be root cause of this multithreading problem. Please let me know if you have any idea.
I have compared Category.java which is a kind of core class for logging functionality in Log4j1.x and Log4j1.x bridge and I see that many methods which we are using were synchronized in log4j1.x but NOT in log4j1.x bridge. I think this could be one of the root causes leading to this problem.
[cid:image001.png@01D84001.E6BD9A00]
Log4j1.x: synchronized public Appender getAppender(String name)
Log4j1.x bridge: public Appender getAppender(final String name)
[cid:image002.png@01D84001.E6BD9A00]
Re: Synchronization issue in multithreading (Losing huge data in multithreading) with log4j 1.x bridge (2.17.2)
Posted by Matt Sicker <bo...@gmail.com>.
None of those attachments made it through to the mailing list.
On Thu, Mar 24, 2022 at 6:22 PM Pooja Pandey <Po...@asg.com.invalid>
wrote:
> Attaching sample test program for simulated multithreading logging.
>
>
>
> *From:* Pooja Pandey <Po...@asg.com.INVALID>
> *Sent:* Friday, March 25, 2022 4:37 AM
> *To:* Log4J Users List <lo...@logging.apache.org>
> *Subject:* Synchronization issue in multithreading (Losing huge data in
> multithreading) with log4j 1.x bridge (2.17.2)
>
>
>
> **** External email: Verify sender before opening attachments or links ****
>
>
>
> Hi,
>
>
>
> In our application we have migrated from log4j1.x to log4j1.x bridge. With
> Log4j1.x there was no issue with multithreading but with log4j 1.x bridge
> we have noticed that in multithreading environment there is a huge data
> loss while logging, however single thread works fine. I see that in
> Category.java which Logger extends; many methods are not synchronized any
> more in log4j1.x bridge however which were in case of log4j1.x. I suspect
> this could be root cause of this multithreading problem. Please let me know
> if you have any idea.
>
>
>
> I have compared Category.java which is a kind of core class for logging
> functionality in Log4j1.x and Log4j1.x bridge and I see that many methods
> which we are using were synchronized in log4j1.x but NOT in log4j1.x
> bridge. I think this could be one of the root causes leading to this
> problem.
>
>
>
>
>
> Log4j1.x: synchronized public Appender getAppender(String name)
>
> Log4j1.x bridge: public Appender getAppender(final String name)
>
>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-user-help@logging.apache.org
RE: Synchronization issue in multithreading (Losing huge data in multithreading) with log4j 1.x bridge (2.17.2)
Posted by Pooja Pandey <Po...@asg.com.INVALID>.
Attaching sample test program for simulated multithreading logging.
From: Pooja Pandey <Po...@asg.com.INVALID>
Sent: Friday, March 25, 2022 4:37 AM
To: Log4J Users List <lo...@logging.apache.org>
Subject: Synchronization issue in multithreading (Losing huge data in multithreading) with log4j 1.x bridge (2.17.2)
*** External email: Verify sender before opening attachments or links ***
Hi,
In our application we have migrated from log4j1.x to log4j1.x bridge. With Log4j1.x there was no issue with multithreading but with log4j 1.x bridge we have noticed that in multithreading environment there is a huge data loss while logging, however single thread works fine. I see that in Category.java which Logger extends; many methods are not synchronized any more in log4j1.x bridge however which were in case of log4j1.x. I suspect this could be root cause of this multithreading problem. Please let me know if you have any idea.
I have compared Category.java which is a kind of core class for logging functionality in Log4j1.x and Log4j1.x bridge and I see that many methods which we are using were synchronized in log4j1.x but NOT in log4j1.x bridge. I think this could be one of the root causes leading to this problem.
[cid:image001.png@01D84001.E6BD9A00]
Log4j1.x: synchronized public Appender getAppender(String name)
Log4j1.x bridge: public Appender getAppender(final String name)
[cid:image002.png@01D84001.E6BD9A00]
Re: Synchronization issue in multithreading (Losing huge data in multithreading) with log4j 1.x bridge (2.17.2)
Posted by Volkan Yazıcı <vo...@yazi.ci>.
Pooja, I think it would be better for attachments and such if you create a
JIRA ticket <https://issues.apache.org/jira/projects/LOG4J2/issues>. What
would be ideal is to share a simple program (a Java file + Log4j
configuration) reproducing the issue in the ticket. This would help us a
lot to troubleshoot what is going on.
On Fri, Mar 25, 2022 at 12:34 AM Pooja Pandey <Po...@asg.com.invalid>
wrote:
> Just for reference, few methods which were synchronized earlier in
> log4j1.x but not anymore in log4j1.x bridge.
>
> 1. public void addAppender(final Appender appender)
>
> 2. public Appender getAppender(final String name)
>
> 3. public void removeAppender(final Appender appender)
>
> 4. public void removeAllAppenders()
>
>
>
> I suspect the methods relating to configuration or getting appenders would
> only be problematic at initialization time.
>
>
>
> The methods we might need to watch for are ones relating to the runtime
> logging methods (e.g. info() warn()). May be the methods chained to in
> log4j2 are not threadsafe. But maybe the bridge itself has some thread
> safety issues.
>
>
>
> Pasting sample code here (Please Note that in this test program, class
> CustomLogger is a dummy class, which you would need to replace with your
> logger)
>
>
>
> package test.common;
>
>
>
> import org.apache.log4j.Logger;
>
> import sun.management.VMManagement;
>
>
>
> import java.io.BufferedWriter;
>
> import java.io.IOException;
>
> import java.lang.management.ManagementFactory;
>
> import java.lang.management.RuntimeMXBean;
>
> import java.lang.reflect.Field;
>
> import java.lang.reflect.Method;
>
> import java.nio.file.Files;
>
> import java.nio.file.Paths;
>
> import java.time.Duration;
>
> import java.time.Instant;
>
> import java.util.ArrayList;
>
> import java.util.List;
>
> import java.util.concurrent.Callable;
>
> import java.util.concurrent.ExecutionException;
>
> import java.util.concurrent.ExecutorService;
>
> import java.util.concurrent.Executors;
>
> import java.util.concurrent.Future;
>
> import java.util.concurrent.TimeUnit;
>
> class CustomLogger extends Logger {
>
> protected CustomLogger(String name) {
>
> super(name);
>
> }
>
>
>
> public static void LogError(String s, Object o) {
>
> }
>
> }
>
> public class JavaLoggingMultiThTest {
>
>
>
> public int pid;
>
>
>
> private class LoggerTask implements Callable<LoggerTask> {
>
> public synchronized void run() {
>
> int logMsgWrittenPerThread;
>
> int maxLogMsgsPerThread = 52224;
>
> for(logMsgWrittenPerThread = 1; logMsgWrittenPerThread <=
> maxLogMsgsPerThread; logMsgWrittenPerThread++) {
>
> CustomLogger.LogError("p:" + pid + ", LM:" +
> Integer.toString(logMsgWrittenPerThread), null);
>
> }
>
> }
>
>
>
> @Override public synchronized LoggerTask call() {
>
> run();
>
> return this;
>
> }
>
> }
>
>
>
> public synchronized void runLoggerTaskMultipleThreads() {
>
> int numThreads = 20;
>
> ArrayList<LoggerTask> loggerTaskList = new ArrayList<LoggerTask>();
>
> for(int i=0; i< numThreads; i++) {
>
> loggerTaskList.add(new LoggerTask());
>
> }
>
> ExecutorService pool = Executors.newFixedThreadPool(numThreads);
>
> try {
>
> Instant startTS = Instant.now();
>
> List<Future<LoggerTask>> waiters =
> pool.invokeAll(loggerTaskList);
>
> boolean allEnded = false;
>
> for (Future waiter : waiters) {
>
> try {
>
> waiter.get();
>
> } catch (InterruptedException | ExecutionException e) {
>
> e.printStackTrace();
>
> }
>
> }
>
> do {
>
> try {
>
> pool.shutdown();
>
> allEnded = pool.awaitTermination(1, TimeUnit.MINUTES);
>
> } catch (InterruptedException e) {
>
> e.printStackTrace();
>
> System.out.println("Interrupted, for some reason");
>
> }
>
> if (!allEnded)
>
> System.out.println("Not ending cleanly");
>
> } while (!allEnded);
>
> Instant endTS = Instant.now();
>
> Duration elapsed = Duration.between(startTS, endTS);
>
> System.out.println("Time taken by current process" + elapsed);
>
> } catch (InterruptedException e) {
>
> e.printStackTrace();
>
> }
>
> }
>
>
>
> private static int getCurrrentProcessId() throws Exception {
>
>
>
> RuntimeMXBean runtime = ManagementFactory.getRuntimeMXBean();
>
> Field jvm = runtime.getClass().getDeclaredField("jvm");
>
> jvm.setAccessible(true);
>
>
>
> VMManagement management = (VMManagement) jvm.get(runtime);
>
> Method method =
> management.getClass().getDeclaredMethod("getProcessId");
>
> method.setAccessible(true);
>
>
>
> return (Integer) method.invoke(management);
>
> }
>
> public static void main(String[] args) throws IOException {
>
>
>
> BufferedWriter writer =
> Files.newBufferedWriter(Paths.get("C:\\Users\\Pooja.Pandey\\vdrws.log"));
>
> writer.write("");
>
> writer.flush();
>
>
>
> JavaLoggingMultiThTest javaLoggingMultiThTest = new
> JavaLoggingMultiThTest();
>
> try {
>
> javaLoggingMultiThTest.pid = getCurrrentProcessId();
>
> } catch (Exception e) {
>
> e.printStackTrace();
>
> }
>
> javaLoggingMultiThTest.runLoggerTaskMultipleThreads();
>
> }
>
> }
>
>
>
>
>
>
>
> *From:* Pooja Pandey <Po...@asg.com.INVALID>
> *Sent:* Friday, March 25, 2022 4:37 AM
> *To:* Log4J Users List <lo...@logging.apache.org>
> *Subject:* Synchronization issue in multithreading (Losing huge data in
> multithreading) with log4j 1.x bridge (2.17.2)
>
>
>
> **** External email: Verify sender before opening attachments or links ****
>
>
>
> Hi,
>
>
>
> In our application we have migrated from log4j1.x to log4j1.x bridge. With
> Log4j1.x there was no issue with multithreading but with log4j 1.x bridge
> we have noticed that in multithreading environment there is a huge data
> loss while logging, however single thread works fine. I see that in
> Category.java which Logger extends; many methods are not synchronized any
> more in log4j1.x bridge however which were in case of log4j1.x. I suspect
> this could be root cause of this multithreading problem. Please let me know
> if you have any idea.
>
>
>
> I have compared Category.java which is a kind of core class for logging
> functionality in Log4j1.x and Log4j1.x bridge and I see that many methods
> which we are using were synchronized in log4j1.x but NOT in log4j1.x
> bridge. I think this could be one of the root causes leading to this
> problem.
>
>
>
>
>
> Log4j1.x: synchronized public Appender getAppender(String name)
>
> Log4j1.x bridge: public Appender getAppender(final String name)
>
>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-user-help@logging.apache.org
RE: Synchronization issue in multithreading (Losing huge data in multithreading) with log4j 1.x bridge (2.17.2)
Posted by Pooja Pandey <Po...@asg.com.INVALID>.
Just for reference, few methods which were synchronized earlier in log4j1.x but not anymore in log4j1.x bridge.
1. public void addAppender(final Appender appender)
2. public Appender getAppender(final String name)
3. public void removeAppender(final Appender appender)
4. public void removeAllAppenders()
I suspect the methods relating to configuration or getting appenders would only be problematic at initialization time.
The methods we might need to watch for are ones relating to the runtime logging methods (e.g. info() warn()). May be the methods chained to in log4j2 are not threadsafe. But maybe the bridge itself has some thread safety issues.
Pasting sample code here (Please Note that in this test program, class CustomLogger is a dummy class, which you would need to replace with your logger)
package test.common;
import org.apache.log4j.Logger;
import sun.management.VMManagement;
import java.io.BufferedWriter;
import java.io.IOException;
import java.lang.management.ManagementFactory;
import java.lang.management.RuntimeMXBean;
import java.lang.reflect.Field;
import java.lang.reflect.Method;
import java.nio.file.Files;
import java.nio.file.Paths;
import java.time.Duration;
import java.time.Instant;
import java.util.ArrayList;
import java.util.List;
import java.util.concurrent.Callable;
import java.util.concurrent.ExecutionException;
import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;
import java.util.concurrent.Future;
import java.util.concurrent.TimeUnit;
class CustomLogger extends Logger {
protected CustomLogger(String name) {
super(name);
}
public static void LogError(String s, Object o) {
}
}
public class JavaLoggingMultiThTest {
public int pid;
private class LoggerTask implements Callable<LoggerTask> {
public synchronized void run() {
int logMsgWrittenPerThread;
int maxLogMsgsPerThread = 52224;
for(logMsgWrittenPerThread = 1; logMsgWrittenPerThread <= maxLogMsgsPerThread; logMsgWrittenPerThread++) {
CustomLogger.LogError("p:" + pid + ", LM:" + Integer.toString(logMsgWrittenPerThread), null);
}
}
@Override public synchronized LoggerTask call() {
run();
return this;
}
}
public synchronized void runLoggerTaskMultipleThreads() {
int numThreads = 20;
ArrayList<LoggerTask> loggerTaskList = new ArrayList<LoggerTask>();
for(int i=0; i< numThreads; i++) {
loggerTaskList.add(new LoggerTask());
}
ExecutorService pool = Executors.newFixedThreadPool(numThreads);
try {
Instant startTS = Instant.now();
List<Future<LoggerTask>> waiters = pool.invokeAll(loggerTaskList);
boolean allEnded = false;
for (Future waiter : waiters) {
try {
waiter.get();
} catch (InterruptedException | ExecutionException e) {
e.printStackTrace();
}
}
do {
try {
pool.shutdown();
allEnded = pool.awaitTermination(1, TimeUnit.MINUTES);
} catch (InterruptedException e) {
e.printStackTrace();
System.out.println("Interrupted, for some reason");
}
if (!allEnded)
System.out.println("Not ending cleanly");
} while (!allEnded);
Instant endTS = Instant.now();
Duration elapsed = Duration.between(startTS, endTS);
System.out.println("Time taken by current process" + elapsed);
} catch (InterruptedException e) {
e.printStackTrace();
}
}
private static int getCurrrentProcessId() throws Exception {
RuntimeMXBean runtime = ManagementFactory.getRuntimeMXBean();
Field jvm = runtime.getClass().getDeclaredField("jvm");
jvm.setAccessible(true);
VMManagement management = (VMManagement) jvm.get(runtime);
Method method = management.getClass().getDeclaredMethod("getProcessId");
method.setAccessible(true);
return (Integer) method.invoke(management);
}
public static void main(String[] args) throws IOException {
BufferedWriter writer = Files.newBufferedWriter(Paths.get("C:\\Users\\Pooja.Pandey\\vdrws.log"));
writer.write("");
writer.flush();
JavaLoggingMultiThTest javaLoggingMultiThTest = new JavaLoggingMultiThTest();
try {
javaLoggingMultiThTest.pid = getCurrrentProcessId();
} catch (Exception e) {
e.printStackTrace();
}
javaLoggingMultiThTest.runLoggerTaskMultipleThreads();
}
}
From: Pooja Pandey <Po...@asg.com.INVALID>
Sent: Friday, March 25, 2022 4:37 AM
To: Log4J Users List <lo...@logging.apache.org>
Subject: Synchronization issue in multithreading (Losing huge data in multithreading) with log4j 1.x bridge (2.17.2)
*** External email: Verify sender before opening attachments or links ***
Hi,
In our application we have migrated from log4j1.x to log4j1.x bridge. With Log4j1.x there was no issue with multithreading but with log4j 1.x bridge we have noticed that in multithreading environment there is a huge data loss while logging, however single thread works fine. I see that in Category.java which Logger extends; many methods are not synchronized any more in log4j1.x bridge however which were in case of log4j1.x. I suspect this could be root cause of this multithreading problem. Please let me know if you have any idea.
I have compared Category.java which is a kind of core class for logging functionality in Log4j1.x and Log4j1.x bridge and I see that many methods which we are using were synchronized in log4j1.x but NOT in log4j1.x bridge. I think this could be one of the root causes leading to this problem.
[cid:image001.png@01D84001.E6BD9A00]
Log4j1.x: synchronized public Appender getAppender(String name)
Log4j1.x bridge: public Appender getAppender(final String name)
[cid:image002.png@01D84001.E6BD9A00]