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

alog refactory #378

Merged
merged 1 commit into from
Feb 26, 2024
Merged

alog refactory #378

merged 1 commit into from
Feb 26, 2024

Conversation

lihuiba
Copy link
Collaborator

@lihuiba lihuiba commented Feb 23, 2024

to make logging completely lazy

Alog used to create a lambda object to do the logging, and the lambda object support lazy evaluation of the parameters of the logging, but the creation of the lambda obj itself is not lazy.

This patch aims to make logging completely lazy, so that the cost of not logging is reduced to a simple if.

For a function like this:

int main(int argc, char** argv) {
	const static char buf[] = "char buf[100]";
	LOG_DEBUG(";laskdjflaskjf", VALUE(argv[0]));
	puts("asdfaskdfj");
	LOG_DEBUG(2, buf, "asdf");
	return 0;
}

gcc will output:

Dump of assembler code for function main:
   0x0000000000400b60 <+0>:	sub    $0x1038,%rsp
   0x0000000000400b67 <+7>:	mov    %edi,0x2014fb(%rip)        # 0x602068 <default_logger+8>
   0x0000000000400b6d <+13>:	mov    %rsi,0x8(%rsp)
   0x0000000000400b72 <+18>:	test   %edi,%edi
   0x0000000000400b74 <+20>:	je     0x400afb <main.cold>
   0x0000000000400b7a <+26>:	mov    $0x400e1a,%edi
   0x0000000000400b7f <+31>:	callq  0x400920 <puts@plt>
   0x0000000000400b84 <+36>:	mov    0x2014de(%rip),%eax        # 0x602068 <default_logger+8>
   0x0000000000400b8a <+42>:	test   %eax,%eax
   0x0000000000400b8c <+44>:	je     0x400b2e <main.cold+51>
   0x0000000000400b92 <+50>:	xor    %eax,%eax
   0x0000000000400b94 <+52>:	add    $0x1038,%rsp
   0x0000000000400b9b <+59>:	retq
End of assembler dump.

Each logging statement generates only 3 instructions in the hot path: loading the log level from logger, test it, and make a conditional jump to actual logging code blocks (marked as cold), while it was compiled to many more instructions:

Dump of assembler code for function main:
   0x0000000000400bc0 <+0>:	sub    $0x38,%rsp
   0x0000000000400bc4 <+4>:	lea    0x8(%rsp),%rax
   0x0000000000400bc9 <+9>:	lea    0x10(%rsp),%rdi
   0x0000000000400bce <+14>:	mov    %rsi,0x8(%rsp)
   0x0000000000400bd3 <+19>:	mov    %rax,(%rsp)
   0x0000000000400bd7 <+23>:	movq   (%rsp),%xmm0
   0x0000000000400bdc <+28>:	movl   $0x0,0x10(%rsp)
   0x0000000000400be4 <+36>:	movhps 0x525(%rip),%xmm0        # 0x401110
   0x0000000000400beb <+43>:	movb   $0x0,0x28(%rsp)
   0x0000000000400bf0 <+48>:	movups %xmm0,0x18(%rsp)
   0x0000000000400bf5 <+53>:	callq  0x400d50 <LogBuilder<main::{lambda(ILogOutput*)#2}>::~LogBuilder() [clone .part.23] [clone .constprop.27]>
   0x0000000000400bfa <+58>:	mov    $0x400f9a,%edi
   0x0000000000400bff <+63>:	callq  0x400980 <puts@plt>
   0x0000000000400c04 <+68>:	lea    0x10(%rsp),%rdi
   0x0000000000400c09 <+73>:	movb   $0x0,0x20(%rsp)
   0x0000000000400c0e <+78>:	movl   $0x0,0x10(%rsp)
   0x0000000000400c16 <+86>:	movq   $0x602060,0x18(%rsp)
   0x0000000000400c1f <+95>:	callq  0x400d30 <LogBuilder<main::{lambda(ILogOutput*)#4}>::~LogBuilder() [clone .part.13] [clone .constprop.24]>
   0x0000000000400c24 <+100>:	xor    %eax,%eax
   0x0000000000400c26 <+102>:	add    $0x38,%rsp
   0x0000000000400c2a <+106>:	retq
End of assembler dump.

@lihuiba lihuiba marked this pull request as ready for review February 25, 2024 04:09
common/alog.h Outdated
#define LOG_WARN_TO(logger, ...) __LOG_COLD__(logger, ALOG_WARN, __VA_ARGS__)
#define LOG_ERROR_TO(logger, ...) __LOG_COLD__(logger, ALOG_ERROR, __VA_ARGS__)
#define LOG_FATAL_TO(logger, ...) __LOG_COLD__(logger, ALOG_FATAL, __VA_ARGS__)
#define LOG_TEMP_TO(logger, ...) { \
Copy link
Collaborator

Choose a reason for hiding this comment

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

better to align tailing back slashes in macro define

common/alog.h Outdated
if (!limiter()) { \
__VA_ARGS__; \
} \
} while(0)
Copy link
Collaborator

Choose a reason for hiding this comment

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

LOG_WITH_LIMITS without tail is confusing.
Since currently LOG is not a value any more, append tail after LogBuffer build is quite hard.
Change the usage of those LOG_EVERY_T LOG_EVERY_N might be better.

Such as LOG_EVERY_T(10, LOG_INFO(...)) change to LOG_INFO(LOG_EVERY_T(10), ...)

Copy link
Collaborator

@Coldwings Coldwings left a comment

Choose a reason for hiding this comment

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

LGTM

@Coldwings Coldwings merged commit 87d0bae into alibaba:main Feb 26, 2024
8 checks passed
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.

2 participants