search

tinylog-org / tinylog

tinylog is a lightweight logging framework for Java, Kotlin, Scala, and Android
https://tinylog.org
Apache License 2.0
697 stars 82 forks source link

Synchronize writing thread with existing writers #634

Closed manisiu closed 9 months ago

manisiu commented 9 months ago

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 commented 9 months ago

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

codecov[bot] commented 9 months ago

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 :warning:
Additional details and impacted files ```diff @@ 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 ```

:umbrella: View full report in Codecov by Sentry.
:loudspeaker: Have feedback on the report? Share it here.

pmwmedia commented 9 months ago

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 commented 9 months ago

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 commented 9 months ago

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 commented 9 months ago

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?

pmwmedia commented 9 months ago

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 commented 9 months ago

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"
pmwmedia commented 9 months ago

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 commented 9 months ago

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!