Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Synchronize writing thread with existing writers #634

Merged
merged 1 commit into from
Dec 29, 2023

Conversation

manisiu
Copy link
Contributor

@manisiu manisiu commented Dec 22, 2023

Description

The writing thread on Android apps can prevent the app from going to sleep as it constantly wakes up every 10ms. I've added synchronisation to wake up only when something is being written. This is critical for our current use case.

@pmwmedia pmwmedia self-assigned this Dec 22, 2023
@pmwmedia pmwmedia added this to the 2.7 milestone Dec 22, 2023
@pmwmedia
Copy link
Member

Thank you for your PR! I like the approach and would like to release it as tinylog 2.7-RC2.

Copy link

codecov bot commented Dec 22, 2023

Codecov Report

Attention: 2 lines in your changes are missing coverage. Please review.

Comparison is base (d216a20) 94.33% compared to head (e0ff744) 94.29%.
Report is 3 commits behind head on v2.7.

Files Patch % Lines
.../src/main/java/org/tinylog/core/WritingThread.java 80.00% 2 Missing ⚠️
Additional details and impacted files
@@             Coverage Diff              @@
##               v2.7     #634      +/-   ##
============================================
- Coverage     94.33%   94.29%   -0.04%     
  Complexity     2829     2829              
============================================
  Files           149      149              
  Lines          5576     5577       +1     
  Branches        722      722              
============================================
- Hits           5260     5259       -1     
- Misses          176      178       +2     
  Partials        140      140              

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

@pmwmedia pmwmedia self-requested a review December 25, 2023 08:41
@pmwmedia
Copy link
Member

I think we have to use only one mutex. Currently, the logging benchmarks are running into a race condition.

With these adjustments, your approach is working for without any race condition and the same throughput as the original implementation:

public final class WritingThread extends Thread {

	private static final String THREAD_NAME = "tinylog-WritingThread";
	private final Object mutex;
	private final Collection<Writer> writers;
	private List<Task> tasks;

	WritingThread(final Collection<Writer> writers) {
		this.mutex = new Object();
		this.writers = writers;
		this.tasks = new ArrayList<Task>();

		setName(THREAD_NAME);
		setPriority(Thread.MIN_PRIORITY);
		setDaemon(true);
	}

	@Override
	public void run() {
		Collection<Writer> writers = new ArrayList<Writer>(1);

		while (true) {
			for (Task task : receiveTasks()) {
				if (task == Task.POISON) {
					close();
					return;
				} else {
					write(writers, task);
				}
			}

			flush(writers);
			writers.clear();
		}
	}

	public void add(final Writer writer, final LogEntry logEntry) {
		Task task = new Task(writer, logEntry);
		synchronized (mutex) {
			tasks.add(task);
			mutex.notify();
		}
	}

	public void shutdown() {
		synchronized (mutex) {
			tasks.add(Task.POISON);
			mutex.notify();
		}
	}

	private List<Task> receiveTasks() {
		synchronized (mutex) {
			while (true) {
				if (tasks.isEmpty()) {
					try {
						mutex.wait();
					} catch (InterruptedException ex) {
						return Collections.emptyList();
					}
				} else {
					List<Task> currentTasks = tasks;
					tasks = new ArrayList<Task>();
					return currentTasks;
				}
			}
		}
	}

	[...]

}
[...]

	<Match>
		<!-- Writing Thread -->
		<Class name="org.tinylog.core.WritingThread" />
		<!-- There is only one writhing thread instance to wake up -->
		<Bug pattern="NO_NOTIFY_NOT_NOTIFYALL" />
	</Match>

[...]

@manisiu Can you have a look? What do you think?

@manisiu
Copy link
Contributor Author

manisiu commented Dec 26, 2023

Thanks for the quick reply and happy holidays!

I'm curious regarding the race condition you mentioned - is there a test I can run to see this in action? As far as I can tell the threadMutex I added just signals the thread and changes nothing regarding the logic, so I wonder where that race condition does occur.

It probably makes sense anyway to use only one mutex as it would make it clearer what's happening and the performance hit is negligible (if any at all).

The code looks good to me, Maybe I'd just simplify receiveTasks a bit with

    private List<Task> receiveTasks() {
        synchronized (mutex) {
            while (tasks.isEmpty()) {
                try {
                    mutex.wait();
                } catch (InterruptedException ex) {
                    return Collections.emptyList();
                }
            }
            List<Task> currentTasks = tasks;
            tasks = new ArrayList<Task>();
            return currentTasks;
        }
    }

I now realised my conditional flushing logic wasn't necessary since the writers are cleared after each iteration, so thanks for getting rid of that. I can update the PR with these changes if that works unless you want to add the changes in yourself. Cheers!

@pmwmedia
Copy link
Member

pmwmedia commented Dec 27, 2023

I'm curious regarding the race condition you mentioned - is there a test I can run to see this in action?

You can execute the logging benchmark to run into the race condition. After installing all tinylog artifact via Maven, you can execute the tinylog benchmarks via the Maven command exec:exec -P benchmark-option-fast,benchmark-tinylog2.

As far as I can tell the threadMutex I added just signals the thread and changes nothing regarding the logic, so I wonder where that race condition does occur.

It happens because it is not guaranteed that the writing thread is already in the waiting state when signaling the thread to wake up.

I can update the PR with these changes if that works unless you want to add the changes in yourself. Cheers!

I like your simplification! You are welcome to update the PR.

Thank you very much for your great contribution! It is really a great improvement for asynchronous logging.

@manisiu
Copy link
Contributor Author

manisiu commented Dec 28, 2023

BTW - running JAVA_HOME=../../jdk-9.0.4+12 mvn --batch-mode --update-snapshots verify fails for me with the following errors:

[ERROR]   DailyPolicyTest$CustomFullTimeTest.init:356 » IllegalAccess Access denied for caller.
[ERROR]   DailyPolicyTest$CustomHourOnlyTimeTest.init:224 » IllegalAccess Access denied for caller.
[ERROR]   DailyPolicyTest$CustomTimeZoneTest.init:522 » IllegalAccess Access denied for caller.
[ERROR]   DailyPolicyTest$CustomTimeZoneTest.init:522 » IllegalAccess Access denied for caller.
[ERROR]   DailyPolicyTest$CustomTimeZoneTest.init:522 » IllegalAccess Access denied for caller.
[ERROR]   DailyPolicyTest$DefaultTimeTest.init:94 » IllegalAccess Access denied for caller.
[ERROR]   DailyPolicyTest$DefaultTimeTest.init:94 » IllegalAccess Access denied for caller.
[ERROR]   MonthlyPolicyTest$CustomFullTimeTest.init:357 » IllegalAccess Access denied for caller.
[ERROR]   MonthlyPolicyTest$CustomHourOnlyTimeTest.init:225 » IllegalAccess Access denied for caller.
[ERROR]   MonthlyPolicyTest$CustomTimeZoneTest.init:524 » IllegalAccess Access denied for caller.
[ERROR]   MonthlyPolicyTest$DefaultTimeTest.init:94 » IllegalAccess Access denied for caller.

I get this with both the maven release in the Linux Mint repos (so Ubuntu) and the latest 3.9,6 binary. I don't usually program in Java, so there might be something obvious I'm missing, but this error seems to say we're accessing some non-public fields through reflection?

@manisiu manisiu marked this pull request as ready for review December 28, 2023 21:43
Copy link
Member

@pmwmedia pmwmedia left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

There are only two minors to improve the PR. Afterwards, it will be ready to merge.

configuration/spotbugs-filters.xml Outdated Show resolved Hide resolved
@pmwmedia
Copy link
Member

BTW - running JAVA_HOME=../../jdk-9.0.4+12 mvn --batch-mode --update-snapshots verify fails for me with the following errors:

[ERROR]   DailyPolicyTest$CustomFullTimeTest.init:356 » IllegalAccess Access denied for caller.
[ERROR]   DailyPolicyTest$CustomHourOnlyTimeTest.init:224 » IllegalAccess Access denied for caller.
[ERROR]   DailyPolicyTest$CustomTimeZoneTest.init:522 » IllegalAccess Access denied for caller.
[ERROR]   DailyPolicyTest$CustomTimeZoneTest.init:522 » IllegalAccess Access denied for caller.
[ERROR]   DailyPolicyTest$CustomTimeZoneTest.init:522 » IllegalAccess Access denied for caller.
[ERROR]   DailyPolicyTest$DefaultTimeTest.init:94 » IllegalAccess Access denied for caller.
[ERROR]   DailyPolicyTest$DefaultTimeTest.init:94 » IllegalAccess Access denied for caller.
[ERROR]   MonthlyPolicyTest$CustomFullTimeTest.init:357 » IllegalAccess Access denied for caller.
[ERROR]   MonthlyPolicyTest$CustomHourOnlyTimeTest.init:225 » IllegalAccess Access denied for caller.
[ERROR]   MonthlyPolicyTest$CustomTimeZoneTest.init:524 » IllegalAccess Access denied for caller.
[ERROR]   MonthlyPolicyTest$DefaultTimeTest.init:94 » IllegalAccess Access denied for caller.

I get this with both the maven release in the Linux Mint repos (so Ubuntu) and the latest 3.9,6 binary. I don't usually program in Java, so there might be something obvious I'm missing, but this error seems to say we're accessing some non-public fields through reflection?

This error usually pops up when Maven uses Java 11 or later. You can execute mvn -v to verify if Maven respects your JAVA_HOME and really uses JDK 9.

@manisiu
Copy link
Contributor Author

manisiu commented Dec 29, 2023

BTW - running JAVA_HOME=../../jdk-9.0.4+12 mvn --batch-mode --update-snapshots verify fails for me with the following errors:

[ERROR]   DailyPolicyTest$CustomFullTimeTest.init:356 » IllegalAccess Access denied for caller.
[ERROR]   DailyPolicyTest$CustomHourOnlyTimeTest.init:224 » IllegalAccess Access denied for caller.
[ERROR]   DailyPolicyTest$CustomTimeZoneTest.init:522 » IllegalAccess Access denied for caller.
[ERROR]   DailyPolicyTest$CustomTimeZoneTest.init:522 » IllegalAccess Access denied for caller.
[ERROR]   DailyPolicyTest$CustomTimeZoneTest.init:522 » IllegalAccess Access denied for caller.
[ERROR]   DailyPolicyTest$DefaultTimeTest.init:94 » IllegalAccess Access denied for caller.
[ERROR]   DailyPolicyTest$DefaultTimeTest.init:94 » IllegalAccess Access denied for caller.
[ERROR]   MonthlyPolicyTest$CustomFullTimeTest.init:357 » IllegalAccess Access denied for caller.
[ERROR]   MonthlyPolicyTest$CustomHourOnlyTimeTest.init:225 » IllegalAccess Access denied for caller.
[ERROR]   MonthlyPolicyTest$CustomTimeZoneTest.init:524 » IllegalAccess Access denied for caller.
[ERROR]   MonthlyPolicyTest$DefaultTimeTest.init:94 » IllegalAccess Access denied for caller.

I get this with both the maven release in the Linux Mint repos (so Ubuntu) and the latest 3.9,6 binary. I don't usually program in Java, so there might be something obvious I'm missing, but this error seems to say we're accessing some non-public fields through reflection?

This error usually pops up when Maven uses Java 11 or later. You can execute mvn -v to verify if Maven respects your JAVA_HOME and really uses JDK 9.

It's definitely JDK 9, I remember having different issues with Java 11. Could it be you're using slightly older versions and some defaults have changed?

mihai@mint:~/tinylog$ JAVA_HOME=../jdk-9.0.4+12 mvn -v

Apache Maven 3.9.6 (bc0240f3c744dd6b6ec2920b3cd08dcc295161ae)
Maven home: /home/mihai/apache-maven-3.9.6
Java version: 9.0.4-adoptopenjdk, vendor: Eclipse OpenJ9, runtime: /home/mihai/jdk-9.0.4+12
Default locale: en_GB, platform encoding: UTF-8
OS name: "linux", version: "6.2.0-33-generic", arch: "amd64", family: "unix"

Copy link
Member

@pmwmedia pmwmedia left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thank you very much! The PR is ready to merge.

@pmwmedia
Copy link
Member

It's definitely JDK 9, I remember having different issues with Java 11. Could it be you're using slightly older versions and some defaults have changed?

mihai@mint:~/tinylog$ JAVA_HOME=../jdk-9.0.4+12 mvn -v

Apache Maven 3.9.6 (bc0240f3c744dd6b6ec2920b3cd08dcc295161ae)
Maven home: /home/mihai/apache-maven-3.9.6
Java version: 9.0.4-adoptopenjdk, vendor: Eclipse OpenJ9, runtime: /home/mihai/jdk-9.0.4+12
Default locale: en_GB, platform encoding: UTF-8
OS name: "linux", version: "6.2.0-33-generic", arch: "amd64", family: "unix"

I see you use OpenJ9. Unfortunately, I have never tested OpenJ9. With OpenJDK 9 it should work.

@pmwmedia
Copy link
Member

I'm happy to merge your changes! Thank you for the great contribution. I will release tinylog 2.7 RC2 within the next days. Wish you all the best for 2024!

@pmwmedia pmwmedia merged commit af087bc into tinylog-org:v2.7 Dec 29, 2023
2 checks passed
@github-actions github-actions bot locked as resolved and limited conversation to collaborators Jan 6, 2024
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
None yet
Development

Successfully merging this pull request may close these issues.

None yet

2 participants