Possible performance improvement for high frequency logging using EquinoxLogWriter

[alxflam-work]

Hi,

i've been taking a look at EquinoxLogWriter recently and noticed the following behavior:

log(FrameworkLogEntry logEntry) always creates a new BufferedWriter with a new FileOutputStream for the given log file as the finally block in log always sets the writer to null (closeFile is called). If one makes heavy usage of logging, this can be a performance issue: Say you log a large number of FrameworkLogEntrys, then the FOS is opened and closed for every single log invocation.

Wouldn't it be possible to improve performance by only re-creating the BufferedWriter when necessary:

• once the log file changes by use of the setter: setOutput is already called by setFile, therefore the writer is closed and set to null
• once the log file rotates due to the max size restriction: checkLogFileSize already calls setOutput and therefore ensures the writer is closed and set to null if the log file changes

As both setFile and log are synchronized, wouldn't it be possible to omit the closeFile call in the log method to keep the writer instance and thereby improving performance for consecutive log invocations? Sure, then there's an open FOS for the runtime of the equinox application, e.g. for the complete runtime of an eclipse RCP. But isn't that somewhat expectable for the log file? A new dispose method may be required which can be called to free the writer and any other members, this could be called e.g. by EquinoxLogServices#stop.

What do you think - is this something that could be improved as outlined? I may just not spot the reason why the writer is not reused.

Greetings,
Alex

[tjwatson]

The log writing code itself predates even Equinox. IIRC the current behavior be necessary for things like the PDE log viewer so that it gets notified when the content of the file changes. At the least we need to make sure the content is flushed to disk each entry write I think.

[alxflam-work]

@tjwatson i think flushing the stream would be fine if the writer is cached, the performance is still improved as the SecurityManager checks as well as the native file opening are then still omitted. This still is a large improvement, e.g. 50k log invocations take ~2s if the writer is reused whereas closing and re-creating the writer on every log invocation yields ~40s. While such large numbers of log invocations usually do not occur, it will still be a minor performance improvement even if logging is not used that frequently.

Regarding the LogView i've checked the code and the view registers itself as a LogListener using the LogReaderService. Therefore, once the log view got created the ExtendedLogReaderServiceFactory will not only have the EquinoxLogWriter as a listener, but additionally the LogView. So the log view is informed about new logs without actually parsing them from the file. There are situations when the log file is actually parsed by the view, e.g. when the view is initially opened.

So i think that such a change should not affect the LogView in eclipse as long as flush is called for every log entry.

[laeubi]

If different classes access the same file, one only needs to make sure it can be shared (e.g. windows don't like to write a file that is currently opened by another process) so this should be checked both on windows/linux to work smoothly.

[tjwatson]

If different classes access the same file, one only needs to make sure it can be shared (e.g. windows don't like to write a file that is currently opened by another process) so this should be checked both on windows/linux to work smoothly.

The log is either instance specific with a unique name contained in the framework storage area, or it has been set to the .log in the workspace data area which has to be locked first before we change the log location to the workspace data area. So I don't think windows file locking behavior should be an issue here since multiple processes should not be using the same log file location.

[tjwatson]

@alxflam-work best way to get this done is to open a PR with your suggested changes. Thanks.

[github-actions]

This issue has been inactive for 180 days and is therefore labeled as stale.
If this issue became irrelevant in the meantime please close it as completed. If it is still relevant and you think it should be fixed some possibilities are listed below.
Please read https://github.com/eclipse-equinox/.github/blob/main/CONTRIBUTING.md#contributing-to-eclipse-equinox for ways to influence development.

[iloveeclipse]

Reopening, change reverted in #388, see discussion on #382.

[github-actions]

This issue has been inactive for 180 days and is therefore labeled as stale.
If this issue became irrelevant in the meantime please close it as completed. If it is still relevant and you think it should be fixed some possibilities are listed below.
Please read https://github.com/eclipse-equinox/.github/blob/main/CONTRIBUTING.md#contributing-to-eclipse-equinox for ways to influence development.