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

[LOGCXX-546] Prevent unnecessary locking when determining the logging level #90

Closed
wants to merge 7 commits into from

Conversation

swebb2066
Copy link
Contributor

throughputtests after these changes:

Benchmarking library only(no writing out):
**************************************************************
Benchmarking Single threaded: 1000000 messages
**************************************************************
Log4cxx NoFormat pattern: %m%n Elapsed: 2.658 secs 376,183/sec
Log4cxx DateOnly pattern: [%d] %m%n Elapsed: 2.665 secs 375,241/sec
Log4cxx DateClassLevel pattern: [%d] [%c] [%p] %m%n Elapsed: 2.688 secs 372,005/sec
Log4cxx Logging with FMT Elapsed: 2.137 secs 468,036/sec
Log4cxx Logging static string Elapsed: 2.143 secs 466,650/sec
Log4cxx Logging static string with FMT Elapsed: 2.245 secs 445,344/sec
Log4cxx Logging disabled debug Elapsed: 0.03112 secs 32,134,432/sec
Log4cxx Logging disabled trace Elapsed: 0.03091 secs 32,355,477/sec
Log4cxx Logging enabled debug Elapsed: 2.142 secs 466,769/sec
Log4cxx Logging enabled trace Elapsed: 2.161 secs 462,705/sec
**************************************************************
Benchmarking multithreaded threaded: 1000000 messages/thread, 4 threads
**************************************************************
Log4cxx Logging with FMT MT Elapsed: 4.19 secs 238,661/sec
Log4cxx Logging with FMT MT Elapsed: 4.233 secs 236,256/sec
Log4cxx Logging with FMT MT Elapsed: 4.315 secs 231,733/sec
Log4cxx Logging with FMT MT Elapsed: 4.324 secs 231,272/sec
**************************************************************
Benchmarking multithreaded disabled: 1000000 messages/thread, 4 threads
**************************************************************
Log4cxx Logging disabled MT Elapsed: 0.03375 secs 29,632,945/sec
Log4cxx Logging disabled MT Elapsed: 0.03366 secs 29,706,781/sec
Log4cxx Logging disabled MT Elapsed: 0.03372 secs 29,653,837/sec
Log4cxx Logging disabled MT Elapsed: 0.03375 secs 29,627,664/sec

throughput output before these changes:

Benchmarking Single threaded: 1000000 messages
**************************************************************
Log4cxx NoFormat pattern: %m%n Elapsed: 2.828 secs 353,625/sec
Log4cxx DateOnly pattern: [%d] %m%n Elapsed: 2.767 secs 361,350/sec
Log4cxx DateClassLevel pattern: [%d] [%c] [%p] %m%n Elapsed: 2.81 secs 355,882/sec
Log4cxx Logging with FMT Elapsed: 2.088 secs 478,949/sec
Log4cxx Logging static string Elapsed: 2.217 secs 451,045/sec
Log4cxx Logging static string with FMT Elapsed: 2.302 secs 434,344/sec
Log4cxx Logging disabled debug Elapsed: 0.1867 secs 5,357,277/sec
Log4cxx Logging disabled trace Elapsed: 0.186 secs 5,375,506/sec
Log4cxx Logging enabled debug Elapsed: 2.261 secs 442,245/sec
Log4cxx Logging enabled trace Elapsed: 2.263 secs 441,886/sec
**************************************************************
Benchmarking multithreaded threaded: 1000000 messages/thread, 4 threads
**************************************************************
Log4cxx Logging with FMT MT Elapsed: 4.097 secs 244,063/sec
Log4cxx Logging with FMT MT Elapsed: 4.105 secs 243,617/sec
Log4cxx Logging with FMT MT Elapsed: 4.132 secs 242,014/sec
Log4cxx Logging with FMT MT Elapsed: 4.132 secs 242,005/sec
**************************************************************
Benchmarking multithreaded disabled: 1000000 messages/thread, 4 threads
**************************************************************
Log4cxx Logging disabled MT Elapsed: 0.6538 secs 1,529,611/sec
Log4cxx Logging disabled MT Elapsed: 0.6681 secs 1,496,778/sec
Log4cxx Logging disabled MT Elapsed: 0.6699 secs 1,492,832/sec
Log4cxx Logging disabled MT Elapsed: 0.6702 secs 1,492,142/sec

@rm5248
Copy link
Contributor

rm5248 commented Dec 29, 2021

Looks good to me. I also get rather dramatic increases in the number of log messages/second when logging is disabled(approx. 10x on my machine). Other stats are about 5-10% better.

@swebb2066
Copy link
Contributor Author

swebb2066 commented Dec 29, 2021

Do you think this performance fix warrants a release (0.12.3) before next_stable is ready?

@rm5248
Copy link
Contributor

rm5248 commented Dec 29, 2021

My current thought is that we'll do a 0.13.0 release in a few weeks; there are a number of fixes for that already in master. next_stable probably won't be for several months at least, since that contains bigger changes(e.g. API breaking, other assorted fixes that are currently hard to fix with the current state of the code without touching pretty much everything).

@ams-tschoening
Copy link
Contributor

Before:

Benchmarking library only(no writing out):
**************************************************************
Benchmarking Single threaded: 1000000 messages
**************************************************************
Log4cxx NoFormat pattern: %m%n Elapsed: 30.14 secs 33.174/sec
Log4cxx DateOnly pattern: [%d] %m%n Elapsed: 24.65 secs 40.569/sec
Log4cxx DateClassLevel pattern: [%d] [%c] [%p] %m%n Elapsed: 22.96 secs 43.549/sec
Log4cxx Logging with FMT Elapsed: 23.98 secs 41.701/sec
Log4cxx Logging static string Elapsed: 9.429 secs 106.055/sec
Log4cxx Logging static string with FMT Elapsed: 28.13 secs 35.551/sec
Log4cxx Logging disabled debug Elapsed: 0.24 secs 4.166.673/sec
Log4cxx Logging disabled trace Elapsed: 0.2271 secs 4.403.643/sec
Log4cxx Logging enabled debug Elapsed: 8.44 secs 118.484/sec
Log4cxx Logging enabled trace Elapsed: 8.734 secs 114.493/sec
**************************************************************
Benchmarking multithreaded threaded: 1000000 messages/thread, 4 threads
**************************************************************
Log4cxx Logging with FMT MT Elapsed: 143 secs 6.991/sec
Log4cxx Logging with FMT MT Elapsed: 143.1 secs 6.988/sec
Log4cxx Logging with FMT MT Elapsed: 143.2 secs 6.984/sec
Log4cxx Logging with FMT MT Elapsed: 143.2 secs 6.982/sec
**************************************************************
Benchmarking multithreaded disabled: 1000000 messages/thread, 4 threads
**************************************************************
Log4cxx Logging disabled MT Elapsed: 0.7581 secs 1.319.082/sec
Log4cxx Logging disabled MT Elapsed: 0.7681 secs 1.301.911/sec
Log4cxx Logging disabled MT Elapsed: 0.7699 secs 1.298.865/sec
Log4cxx Logging disabled MT Elapsed: 0.775 secs 1.290.337/sec

After:

Benchmarking library only(no writing out):
**************************************************************
Benchmarking Single threaded: 1000000 messages
**************************************************************
Log4cxx NoFormat pattern: %m%n Elapsed: 30.23 secs 33.075/sec
Log4cxx DateOnly pattern: [%d] %m%n Elapsed: 19.43 secs 51.465/sec
Log4cxx DateClassLevel pattern: [%d] [%c] [%p] %m%n Elapsed: 18.13 secs 55.144/sec
Log4cxx Logging with FMT Elapsed: 21.12 secs 47.337/sec
Log4cxx Logging static string Elapsed: 7.319 secs 136.623/sec
Log4cxx Logging static string with FMT Elapsed: 24.16 secs 41.388/sec
Log4cxx Logging disabled debug Elapsed: 0.04665 secs 21.436.181/sec
Log4cxx Logging disabled trace Elapsed: 0.04477 secs 22.333.941/sec
Log4cxx Logging enabled debug Elapsed: 7.426 secs 134.654/sec
Log4cxx Logging enabled trace Elapsed: 7.309 secs 136.813/sec
**************************************************************
Benchmarking multithreaded threaded: 1000000 messages/thread, 4 threads
**************************************************************
Log4cxx Logging with FMT MT Elapsed: 140.7 secs 7.105/sec
Log4cxx Logging with FMT MT Elapsed: 141.1 secs 7.088/sec
Log4cxx Logging with FMT MT Elapsed: 141.2 secs 7.081/sec
Log4cxx Logging with FMT MT Elapsed: 141.3 secs 7.078/sec
**************************************************************
Benchmarking multithreaded disabled: 1000000 messages/thread, 4 threads
**************************************************************
Log4cxx Logging disabled MT Elapsed: 0.03834 secs 26.083.917/sec
Log4cxx Logging disabled MT Elapsed: 0.04217 secs 23.711.966/sec
Log4cxx Logging disabled MT Elapsed: 0.0465 secs 21.504.821/sec
Log4cxx Logging disabled MT Elapsed: 0.05066 secs 19.740.686/sec

@swebb2066
Copy link
Contributor Author

Is this good to merge?

@swebb2066 swebb2066 closed this Jan 1, 2022
@swebb2066
Copy link
Contributor Author

Merged using https://gitbox.apache.org

@swebb2066 swebb2066 deleted the increase_throughput branch January 1, 2022 04:39

/**
Return the the LoggerRepository where this
<code>Logger</code> is attached.
*/
log4cxx::spi::LoggerRepositoryWeakPtr getLoggerRepository() const;
log4cxx::spi::LoggerRepository* getLoggerRepository() const;
Copy link
Contributor

Choose a reason for hiding this comment

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

After thinking about this for a few days, would it be better to lave this as LoggerRepositoryWeakPtr? The signature of this method did change about a year ago(so some people have started fixing their code to use it), and I would hate to ping-pong back and forth over the signature of the method.

If we just change the Logger::setHierarchy to lock the pointer that is passed in(and store the raw pointer as a new member), I think that would be less of a change and less likely to break things.

I don't have a problem changing it in the next_stable branch, since my hope would be that we can clean up the initialization sequence of things to make it more clean as well.

Thoughts?

Copy link
Contributor Author

@swebb2066 swebb2066 Jan 1, 2022

Choose a reason for hiding this comment

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

I will measure the impact with 'm->priv->repository' a weak pointer.

With this PR included, LOG4CXX_322 is still a probem. I still eventually get a SegFault in multithreadtest using the following:

while ctest -R multi; do i=`expr $i + 1`; echo Done $i; done;

However, with 'm->priv->repository' a weak pointer, getLoggerRepository() should return a spi::LoggerRepositoryPtr (i.e. getLoggerRepository() should call lock()), so the caller does not need to call lock().

Copy link
Contributor Author

@swebb2066 swebb2066 Jan 2, 2022

Choose a reason for hiding this comment

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

The per thread throughput is less half the single thread throughput when using a std::weak_ptr in Logger (Results are in #94)

Also, LOGCXX-322 is still a problem when using a std::weak_ptr in Logger.

Copy link
Contributor

Choose a reason for hiding this comment

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

I agree that using the raw pointer would be faster, but what I'm saying is why don't we store the raw pointer and the weak pointer? That lets the API stay stable, plus gives us the benefits of speed since we only use the raw pointer.

pseudo-code:
Logger.h:

private:
  log4cxx::spi::LoggerRepositoryWeakPtr repository;
  log4cxx::spi::LoggerRepository* repository_raw;

Logger.cpp:

void Logger::setHierarchy(spi::LoggerRepositoryWeakPtr repository1)
{
	this->repository = repository1;
        this->repository_raw = repository1.lock().get();
}

bool Logger::isTraceEnabled() const
{
	if (!repository_raw || repository_raw->isDisabled(Level::TRACE_INT))
	{
		return false;
	}
        return true;
}

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Given the std::weak_ptr does not fix LOGCXX-322, why is it is useful?

Copy link
Contributor

Choose a reason for hiding this comment

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

Even if it doesn't completely fix it, there are at least two reasons that I can think of:

  • Since it is part of the public API, it forces clients to use smart pointers(better expressing the intent) and keeps it similar to other parts of the API
  • Keeps things stable for users who need to get the repository from the logger

Copy link
Contributor

Choose a reason for hiding this comment

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

I expect that there's also a better way to fix this that requires some bigger architecture changes; I don't know what those are at the moment, but hopefully we can fix it for next_stable.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

OK, I agree forceing clients to use smart pointers better expresses the intent.

So, I will change getLoggerRepository() to

log4cxx::spi::LoggerRepositoryPtr getLoggerRepository() const

OK?

Copy link
Contributor

Choose a reason for hiding this comment

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

sounds good to me.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

4 participants