Remove SDS logging in debug builds

[389-ds-bot]

Cloned from Pagure issue: https://pagure.io/389-ds-base/issue/49310

• Created at 2017-07-04 04:12:25 by firstyear (@Firstyear)
• Closed at 2017-07-17 04:08:19 as fixed
• Assigned to firstyear (@Firstyear)

---

Issue Description

During debug builds most people don't utilise SDS logging. We should change the #define it uses to remove it during debug builds in this case.

[389-ds-bot]

Comment from firstyear (@Firstyear) at 2017-07-04 05:35:05

[389-ds-bot]

Comment from firstyear (@Firstyear) at 2017-07-04 05:35:06

Metadata Update from @Firstyear:

• Custom field reviewstatus adjusted to review
• Custom field type adjusted to defect
• Issue assigned to Firstyear

[389-ds-bot]

Comment from lslebodn at 2017-07-04 11:03:04

IMHO, people tent to forget that they should use #ifdef around debug functions. It would be good to use #ifdef on single place and simplify life for everyone.

untested POC:

diff --git a/src/libsds/sds/sds_internal.h b/src/libsds/sds/sds_internal.h
index e05f408..6474b24 100644
--- a/src/libsds/sds/sds_internal.h
+++ b/src/libsds/sds/sds_internal.h
@@ -27,6 +27,12 @@

 #define SDS_CACHE_ALIGNMENT 64

-void sds_log(char *id, char *msg, ...);
+#ifdef SDS_DEBUG
+#define sds_debug(id, msg, ...) _sds_debug(id, msg, ##__VA_ARGS__)
+#else
+#define sds_debug(id, msg, ...)
+#endif
+
+void _sds_log(char *id, char *msg, ...);

[389-ds-bot]

Comment from firstyear (@Firstyear) at 2017-07-05 01:15:55

Using macros for functions breaks the understanding and reasoning about how a function works. Is it a function? A macro? when is it included? What is the effect on my code? can I set a break point in gdb on the sds_debug function now?

I'd rather have this setup, where the log function refuses to compile (unless it's wrapped in the same #ifdef). This way:

• we can eliminate some code paths because some messages are informative only, so we can just remove the if statements involved.
• sds_debug is still always a function, no matter what. There is no ambiguity about it's design.
• people can not forget to wrap this in the #ifdef because the code will not compile.

I chose my solution with these factors in mind,

Thanks,

[389-ds-bot]

Comment from mreynolds (@mreynolds389) at 2017-07-05 15:29:35

Metadata Update from @mreynolds389:

• Custom field reviewstatus adjusted to ack (was: review)

[389-ds-bot]

Comment from lslebodn at 2017-07-05 16:51:13

There is a typo in previous comment. It should have been macro sss_log which conditionally expands to calling function _sss_log

diff --git a/src/libsds/sds/sds_internal.h b/src/libsds/sds/sds_internal.h
index e05f408..6474b24 100644
--- a/src/libsds/sds/sds_internal.h
+++ b/src/libsds/sds/sds_internal.h
@@ -27,6 +27,12 @@

 #define SDS_CACHE_ALIGNMENT 64

-void sds_log(char *id, char *msg, ...);
+#ifdef SDS_DEBUG
+#define sds_log(id, msg, ...) _sds_debug(id, msg, ##__VA_ARGS__)
+#else
+#define sds_log(id, msg, ...)
+#endif
+
+void _sds_log(char *id, char *msg, ...);

Using macros for functions breaks the understanding and reasoning about >how a function works.

It does not. Reasonable using of macros reduce ugly code.

Is it a function?

yes _sss_log will still be a function. But setting a breakpoint to debug function is really unusual.

A macro? when is it included? What is the effect on my code? can I set a break point in gdb on the sds_debug function now?

Yes you can set a breakpoint to function _sss_log

I'd rather have this setup, where the log function refuses to compile (unless >it's wrapped in the same #ifdef). This way:

Your will compile if you forget #ifdef SDS_DEBUG and that's the biggest problem of the patch. My proposal will not enforce it globally. And it still will be type safe because _sss_log is renamed current function sss_log

BTW current verision of sss_log is not type safe either because there is missing __attribute__((format)) which could enforce type safe parameters.

• we can eliminate some code paths because some messages are >informative only, so we can just remove the if statements involved.

I thought that it should be handled by log level :-) Which is missing in sds_log.

• sds_debug is still always a function, no matter what. There is no >ambiguity about it's design.

I think you meant sds_log here.

• people can not forget to wrap this in the #ifdef because the code will not >compile.

Developers forget and they will forget in future as well. The implementation of function sds_log is not conditionally built. Therefore you cannot achieve missing ifdef around by compiler with current patch.

And Nice examples are on lines 2038, 2047, 2054 (in patch).

• many others

I chose my solution with these factors in mind,

I do not force anyone to implement anything. If you thing you solution is better then feel free to push it. I have different opinion and you still haven't persuaded me :-)

[389-ds-bot]

Comment from firstyear (@Firstyear) at 2017-07-06 04:46:59

It does not. Reasonable using of macros reduce ugly code.

I'm yet to see examples of this. I think macros make it harder to trace code - for example, in GDB when you list a prog, the macro isn't expanded. You have no visibility into what is going on inside. You can't set a break point in the middle of the macro, etc. Macros in C are not a nice thing IMO.

Yes you can set a breakpoint to function _sss_log

Only if you know that it's a macro.

Developers forget and they will forget in future as well. The implementation of function sds_log is not conditionally built. Therefore you cannot achieve missing ifdef around by compiler with current patch.

sds_log is built static if debug is not defined. That contains it just to the utils.c file so we can emit msgs when we can malloc. This way it still won't let anything use it if you don't wrap it in the define (you get implicit declaration). So we still are protected in this case.

[389-ds-bot]

Comment from firstyear (@Firstyear) at 2017-07-06 04:47:31

Update that adds the attribute((format)) as suggested by @lslebodn (which was a good tip!)

[389-ds-bot]

Comment from lslebodn at 2017-07-06 11:09:53

It does not. Reasonable using of macros reduce ugly code.

I'm yet to see examples of this. I think macros make it harder to trace code - for example, in GDB when you list a prog, the macro isn't expanded. You have no visibility into what is going on inside. You can't set a break point in the middle of the macro, etc. Macros in C are not a nice thing IMO.

Yes you can set a breakpoint to function _sss_log

Only if you know that it's a macro.

As I mentioned in previous comment is very unusual to set breakpoints on debug functions. And you will not be able to set breakpoint do sds_log even with this patch because functions won't be compiled by defualt. So this point is invalid.

Developers forget and they will forget in future as well. The implementation of function sds_log is not conditionally built. Therefore you cannot achieve missing ifdef around by compiler with current patch.

sds_log is built static if debug is not defined. That contains it just to the utils.c file so we can emit msgs when we can malloc. This way it still won't let anything use it if you don't wrap it in the define (you get implicit declaration). So we still are protected in this case.

But static function does not guarantee that will not be used at all. Static function sds_log with undefined SDS_DEBUG will still can be used in module utils.c and thus indirectly on many places. developers can forget to add ifdef there.

Performance of my proposal would be much better and conditional build will be solved on single place.

BTW such using of macros is much uglier then wrapper around function. But that's my personal opinion.

I understand that debug logging in libsds decrease performance and should not be compiled by default. But is there a reason why it cannot be solved on single place instead of on 209 places? BTW #ifdef SDS_DEBUG needn't be in macro. You can put it into function sds_log and compiler will optimize out invocation of empty function in case of undefined SDS_DEBUG

e.g.

diff --git a/src/libsds/sds/core/utils.c b/src/libsds/sds/core/utils.c
index ee6cfcb..e626829 100644
--- a/src/libsds/sds/core/utils.c
+++ b/src/libsds/sds/core/utils.c
@@ -69,6 +69,7 @@ sds_strdup(void *key) {
  */
 void
 sds_log(char *id, char *msg, ...) {
+#ifdef SDS_DEBUG
     printf("%s: ", id);
     va_list subs;
     va_start(subs, msg);
@@ -76,6 +77,7 @@ sds_log(char *id, char *msg, ...) {
     va_end(subs);
     printf("\n");
     return;
+#endif
 }

It won't be optimized out in case of -O0 but production code is never compiled with -O0 and invocation of empty function is not a huge overhead.

[389-ds-bot]

Comment from firstyear (@Firstyear) at 2017-07-07 02:32:54

@lslebodn We can agree to disagree :) I have too many bad experiences with macros and their "faults" I think.

[389-ds-bot]

Comment from lslebodn at 2017-07-07 13:12:55

@lslebodn We can agree to disagree :) I have too many bad experiences with macros and their "faults" I think.

But it still does not explain why it cannot be solved on single place. I proposed solution even without macros.

[389-ds-bot]

Comment from lkrispen (@elkris) at 2017-07-07 13:34:59

I'm late in the discussion. But like some do dislike macros, I am not a friend of ifdefs, and if they are nested it gets horrible. And if you wan to change behaviour you need to recompile, nothing what you want to do if debugging a problem in a customer deployment. I would have the logging code always available and trigger its execution by (configurable) log or dbg level

[389-ds-bot]

Comment from lslebodn at 2017-07-07 13:41:56

I'm late in the discussion. But like some do dislike macros, I am not a friend of ifdefs, and if they are nested it gets horrible. And if you wan to change behaviour you need to recompile, nothing what you want to do if debugging a problem in a customer deployment. I would have the logging code always available and trigger its execution by (configurable) log or dbg level

That's reasonable request. And usually logging in libraries is not done to stdout but via registered callback. And you could register callback based on configuration option As Ludwig suggested.

If logging in libsds is just for developer purposes then proposal from #2369#comment-447627 should be sufficient and solved on single place.

[389-ds-bot]

Comment from firstyear (@Firstyear) at 2017-07-13 06:16:41

Look, there is a reason I ifdef this code. There are branches we don't need to check or take during a production build. It's not like this is stuff called a hand full of times, we're talking in the thousands per second, this is stuff in the hot parts of the code, where every extra fn call causes extra delay (even if it's no-op).

As fun as it is to bikeshed about all the different ways we love to style our code, my decisions were made carefully and for good reasons about the specifics of this library - which I am intimately familiar with given I wrote all it.

I'm not altering the patch based on anyone's "opinions" at this point - only if there is a genuine bug or issue you can find.

Thanks,

[389-ds-bot]

Comment from lslebodn at 2017-07-14 10:45:28

Look, there is a reason I ifdef this code.

OK, but with your patchset ifdef is almost around all invocation of log function. Is there a reason why it cannot be solved on single place but it need to be on 209 places?

You can have two function sds_log wich will log in all cases and sds_debug just for your purpose which will be optimized out by compiler.

[389-ds-bot]

Comment from firstyear (@Firstyear) at 2017-07-14 12:13:30

I code my way. You code yours. I'm not here to argue your style vs mine. I have practical reasons for my decisions even if you don't care to understand them. At the end of the day I'm the one who has the burden of this decision and responsibility to maintain it, so if this is how I want it, then who cares.

[389-ds-bot]

Comment from lslebodn at 2017-07-14 21:28:44

I code my way. You code yours. I'm not here to argue your style vs mine. I have practical reasons for my decisions even if you don't care to understand them.

It is not about me. Because it is very likely I will never use it. But any other contributor will not be sure why it need to be done in such unusual way.

Such implementation of logging violate many programming principles[1,2,3,4,5] which I didn't invented. The ideal would be to implement logging with AOP[6] but there is not standard implementation for ansi-C which does not require extra compiler. But we can still follow best programming principles and solve it on single place. But feel free to teach me something and explain why it is not a good idea to follow best practices.

[1] https://en.wikipedia.org/wiki/Code_reuse [2] https://en.wikipedia.org/wiki/Separation_of_concerns [3] https://en.wikipedia.org/wiki/Coupling_(computer_programming) [4] https://en.wikipedia.org/wiki/Don%27t_repeat_yourself [5] https://en.wikipedia.org/wiki/Single_responsibility_principle [6] https://en.wikipedia.org/wiki/Aspect-oriented_programming

[389-ds-bot]

Comment from firstyear (@Firstyear) at 2017-07-17 01:39:41

Just because everyone says "jump off the cliff" do you? "best-practice" is the same. It's not always what's best, but what most people do.

C is a garbage fire language. It's awful. Everything about working in C is like walking through a broken glass factory with no shoes on. Think die hard. Do you know what the complier will do to your code? Do you know what's a macro and what's not? Lets look at:

for (int i = 0; i < numelements; i++) {
    if (cond == 0) {
          debug_log(....);
    }
}

What does this code do? Hint: you can't answer. It's C. You literally have no idea. First, cond, debug_log or numelements could be macros. Or variables. Or a variable being overwriten by a macro. What about the order of operations? What if debug_log has a macro that says "do nothing" inside it. But I WROTE code that says debug, so why isn't it working? What about compiler? What does the complier do here? What will it re-arrange, eliminate? You don't know. You have no idea. Because screw everything, this is C. All bets are off.

Imagine running this under gdb and then a WHOLE BLOCK of your program is just skipped. You would be scratching your head saying "the fuck?" for about 20 minutes until you realised you got burnt by dead code elimination.

Bonus marks for if you noticed that int is the wrong type for indexing array but BEST PRACTICE is everyone uses int for array indexes. GREAT ISNT IT!

Instead of letting the compiler do mystery shit behind my back, I want to know exactly what's going on. So when you have:

func(char *) {
    #ifndef X
    #endif
}

main (...) {
     if (cond) {
            func(....)
     }
} 

Can you without and shadow of a doubt, tell me that every single time I compile this in any conditions that the "if (cond)" will eliminated if X is true?

No. Because you don't know. I sure don't.

Instead I want to be explicit about the intent of my program. You take one look and you know that this code is only in a debug build. You know what conditions it will be compiled under, and why.

I do not like implicit magic. I hate it. I despise it. Explict is always better. Even if it means "209 more lines" instead of 1 magic line. Because you are confusing "efficency" with "human interaction". Sure, it's nice to have the perfect 1 spot solution. But humans, have to read this. And fact is you, I, no one on this team can claim to understand C and compilers perfectly internally. So instead, these "optimisations" and "elegant" patterns you propose end up in a snake-mess of code where you can't work out why there are 13 layers of indirection and why this code won't run. Then one day someone needs to have that "one debug" line run, but their choice is "all 1000 of them", or "none of them". So they add a new type .... the mess grows. And that mess becomes a project, and these "best practices" are what has left us with the horrid mess that is the current state of every C program in the world.

And guess what. My approach is working for me, and this project. We have seen a huge reduction in incoming crashes and issues, we are starting to get more confident with refactors and major changes, and this situation will only improve as we start to accept that code needs to be read by humans.

So let's look at this example again:

#ifdef DEBUG
for (int i = 0; i < numelements; i++) {
    if (cond == 0) {
          debug_log(....);
    }
}
#endif

I sure think there are still lots of issues here, but I know exactly when this code will be built, when it will be run, and I have no concerns over what "compiler magic" is going on. Because when it's built, debugg_log will DO SOMETHING, so this loop must concretely exist in the final output. No ambiguity. No confusion. You know when and why this is running. You know it will be there in gdb. You know it won't be in production.

This is code that is parseable by a human with zero loss to the machine.

[389-ds-bot]

Comment from mreynolds (@mreynolds389) at 2017-07-17 02:22:56

My ack still stands. LGTM, both ways are acceptable - it's nothing to argue over.

[389-ds-bot]

Comment from firstyear (@Firstyear) at 2017-07-17 04:08:20

commit 8f42060fa5c34fcb78f1e0a9a7d62fda030c6258 To ssh://git@pagure.io/389-ds-base.git b882685..8f42060 master -> master

[389-ds-bot]

Comment from firstyear (@Firstyear) at 2017-07-17 04:08:20

Metadata Update from @Firstyear:

• Issue close_status updated to: fixed
• Issue status updated to: Closed (was: Open)