Example:

[05/Jan/2015:10:25:28 +0000] conn=16972 op=4 RESULT err=0 tag=101 nentries=0 etime=0 notes=P
[05/Jan/2015:10:25:30 +0000] conn=5 op=176710 SRCH base="dc=dev,dc=example,dc=com" scope=2 filter="(&(|(objectClass=krbprincipalaux)(objectClass=krbprincipal)(objectClass=ipakrbprincipal))(|(ipaKrbPrincipalAlias=host/ipaserver01.dev.example.com@DEV.EXAMPLE.COM)(krbPrincipalName=host/ipaserver01.dev.example.com@DEV.EXAMPLE.COM)))" attrs="stuff in here"
[05/Jan/2015:10:25:30 +0000] conn=5 op=176711 SRCH base="cn=DEV.EXAMPLE.COM,cn=kerberos,dc=dev,dc=example,dc=com" scope=0 filter="(objectClass=krbticketpolicyaux)" attrs="stuff in here"
[05/Jan/2015:10:25:30 +0000] conn=5 op=176711 RESULT err=0 tag=101 nentries=1 etime=0
[05/Jan/2015:10:25:30 +0000] conn=5 op=176712 SRCH base="dc=dev,dc=example,dc=com" scope=2 filter="(&(|(objectClass=krbprincipalaux)(objectClass=krbprincipal)(objectClass=ipakrbprincipal))(|(ipaKrbPrincipalAlias=krbtgt/DEV.EXAMPLE.COM@DEV.EXAMPLE.COM)(krbPrincipalName=krbtgt/DEV.EXAMPLE.COM@DEV.EXAMPLE.COM)))" attrs="stuff in here"
[05/Jan/2015:10:25:30 +0000] conn=5 op=176710 RESULT err=0 tag=101 nentries=1 etime=0
[05/Jan/2015:10:25:30 +0000] conn=5 op=176713 SRCH base="cn=global_policy,cn=DEV.EXAMPLE.COM,cn=kerberos,dc=dev,dc=example,dc=com" scope=0 filter="(objectClass=)" attrs="stuff in here"
[05/Jan/2015:10:25:30 +0000] conn=5 op=176713 RESULT err=0 tag=101 nentries=1 etime=0
[05/Jan/2015:10:25:30 +0000] conn=5 op=176712 RESULT err=0 tag=101 nentries=1 etime=0
[05/Jan/2015:10:25:30 +0000] conn=5 op=176714 SRCH base="dc=dev,dc=example,dc=com" scope=2 filter="(&(|(objectClass=krbprincipalaux)(objectClass=krbprincipal)(objectClass=ipakrbprincipal))(|(ipaKrbPrincipalAlias=host/ipaserver01.dev.example.com@DEV.EXAMPLE.COM)(krbPrincipalName=host/ipaserver01.dev.example.com@DEV.EXAMPLE.COM)))" attrs="stuff in here"
[05/Jan/2015:10:25:30 +0000] conn=5 op=176715 SRCH base="cn=DEV.EXAMPLE.COM,cn=kerberos,dc=dev,dc=example,dc=com" scope=0 filter="(objectClass=krbticketpolicyaux)" attrs="stuff in here"
[05/Jan/2015:10:25:30 +0000] conn=5 op=176715 RESULT err=0 tag=101 nentries=1 etime=0
[05/Jan/2015:10:25:30 +0000] conn=5 op=176716 SRCH base="dc=dev,dc=example,dc=com" scope=2 filter="(&(|(objectClass=krbprincipalaux)(objectClass=krbprincipal)(objectClass=ipakrbprincipal))(|(ipaKrbPrincipalAlias=krbtgt/DEV.EXAMPLE.COM@DEV.EXAMPLE.COM)(krbPrincipalName=krbtgt/DEV.EXAMPLE.COM@DEV.EXAMPLE.COM)))" attrs="stuff in here"
[05/Jan/2015:10:25:30 +0000] conn=5 op=176714 RESULT err=0 tag=101 nentries=1 etime=0
[05/Jan/2015:10:25:30 +0000] conn=5 op=176717 SRCH base="cn=global_policy,cn=DEV.EXAMPLE.COM,cn=kerberos,dc=dev,dc=example,dc=com" scope=0 filter="(objectClass=)" attrs="stuff in here"
[05/Jan/2015:10:25:30 +0000] conn=5 op=176717 RESULT err=0 tag=101 nentries=1 etime=0
[05/Jan/2015:10:25:30 +0000] conn=5 op=176718 MOD dn="fqdn=ipaserver01.dev.example.com,cn=computers,cn=accounts,dc=dev,dc=example,dc=com"
[05/Jan/2015:10:25:30 +0000] conn=5 op=176716 RESULT err=0 tag=101 nentries=1 etime=0
[05/Jan/2015:10:25:30 +0000] conn=5 op=176718 RESULT err=0 tag=103 nentries=0 etime=0 csn=54aa66dc000100030000
[05/Jan/2015:10:25:30 +0000] conn=5 op=176719 SRCH base="dc=dev,dc=example,dc=com" scope=2 filter="(&(|(objectClass=krbprincipalaux)(objectClass=krbprincipal))(krbPrincipalName=krbtgt/DEV.EXAMPLE.COM@DEV.EXAMPLE.COM))" attrs="stuff in here"
[05/Jan/2015:10:25:30 +0000] conn=5 op=176720 SRCH base="dc=dev,dc=example,dc=com" scope=2 filter="(&(|(objectClass=krbprincipalaux)(objectClass=krbprincipal)(objectClass=ipakrbprincipal))(|(ipaKrbPrincipalAlias=ldap/ipaserver01.dev.example.com@DEV.EXAMPLE.COM)(krbPrincipalName=ldap/ipaserver01.dev.example.com@DEV.EXAMPLE.COM)))" attrs="stuff in here"
[05/Jan/2015:10:25:30 +0000] conn=5 op=176719 RESULT err=0 tag=101 nentries=1 etime=0
[05/Jan/2015:10:25:30 +0000] conn=5 op=176721 SRCH base="cn=DEV.EXAMPLE.COM,cn=kerberos,dc=dev,dc=example,dc=com" scope=0 filter="(objectClass=krbticketpolicyaux)" attrs="stuff in here"
[05/Jan/2015:10:25:30 +0000] conn=5 op=176721 RESULT err=0 tag=101 nentries=1 etime=0
[05/Jan/2015:10:25:30 +0000] conn=5 op=176722 SRCH base="dc=dev,dc=example,dc=com" scope=2 filter="(&(|(objectClass=krbprincipalaux)(objectClass=krbprincipal))(krbPrincipalName=host/ipaserver01.dev.example.com@DEV.EXAMPLE.COM))" attrs="stuff in here"
[05/Jan/2015:10:25:30 +0000] conn=5 op=176720 RESULT err=0 tag=101 nentries=1 etime=0
[05/Jan/2015:10:25:30 +0000] conn=5 op=176723 SRCH base="cn=DEV.EXAMPLE.COM,cn=kerberos,dc=dev,dc=example,dc=com" scope=0 filter="(objectClass=krbticketpolicyaux)" attrs="stuff in here"
[05/Jan/2015:10:25:30 +0000] conn=5 op=176723 RESULT err=0 tag=101 nentries=1 etime=0
[05/Jan/2015:10:25:30 +0000] conn=5 op=176722 RESULT err=0 tag=101 nentries=1 etime=0
[05/Jan/2015:10:25:30 +0000] conn=16971 op=9 EXT oid="2.16.840.1.113730.3.5.12" name="replication-multimaster-extop"
[05/Jan/2015:10:25:30 +0000] conn=16971 op=9 RESULT err=0 tag=120 nentries=0 etime=0
[05/Jan/2015:10:25:33 +0000] conn=16971 op=11 EXT oid="2.16.840.1.113730.3.5.5" name="Netscape Replication End Session"

30 entries timestamped with "[05/Jan/2015:10:25:30 +0000]". Ordering is completely lost by the time this data reaches the ElasticSearch server that stores all our logs.

This will also require a change in logconv, in admin express, and in the console.

Ticket has been cloned to Bugzilla: https://bugzilla.redhat.com/show_bug.cgi?id=1273549

Best bet will be:

http://linux.die.net/man/3/clock_gettime
http://www.gnu.org/software/libc/manual/html_node/Elapsed-Time.html

Then we just do snprintf on the result of strfrmt in log.c log_convert_time() to include the nanoseconds. Should yield:
{{{
13:41:17.994326501
}}}

I think that it should be configurable to enable high precision timestamps. Some sites may have systems with regex based log extraction and this change may break them.

We will obviously need to convert admin, logconv and others to understand both.

Alternately, we could make a decision to just adopt the new format if that is easier.

Okay, these logs with HR timestamps are now:

{{{
[05/Feb/2016:14:09:24.321258939 +1000] conn=47463 op=0 BIND dn="uid=test1585,dc=example,dc=com" method=128 version=3
}}}

If we look in the code, we maintain a "string cache". IE if we have calculated the string buffer for the timestamp in the last second, we re-use it rather than generating a new one.

However, it looks like this slightly hampers performance as this creates a locking bottleneck around the timestamp str cache.

I've tested the combinations of HR and second precision, as well as cache and no cache.

Here are the results.

{{{
/opt/dirsrv/bin/ldclt -h localhost -p 389 -e bindeach,bindonly -D uid=testXXXX,dc=example,dc=com -w passwordXXXX -e randombinddn,randombinddnlow=0,randombinddnhigh=9999 -e esearch -f "(&(objectClass=posixAccount)(uid=1))"

HR With str cache:

ldclt[30925]: Average rate: 552.60/thr ( 552.60/sec), total: 5526

HR no str cache

ldclt[21057]: Average rate: 608.00/thr ( 608.00/sec), total: 6080

Sec with str cache <<-- current

ldclt[11190]: Average rate: 622.60/thr ( 622.60/sec), total: 6226

Sec with no str cache

ldclt[1295]: Average rate: 636.00/thr ( 636.00/sec), total: 6360
}}}

This was performed on my laptop. I allowed the test to run until a stable result was achieved.

This shows that removing the string cache in both cases will improve performance of the log by 2% or more.

Additionally, it shows that there is only a 4% perf difference between HR time stamps and sec precision timestamps.

I think that to improve this, we need to move the string formatting to the log buffer thread. At the moment, this is currently conducted in the search thread as we need the timestamp "now", rather than the time stamp when the log is written.

This should help to negate any perf change between these functions, and would improve logging performance overall.

I would like to thus propose:

• We drop the string caching from both sec precision and HR timestamps. I'll leave the code for it in place but commented so we can re-enable later if we wish.
• We move the timestamp formatting to the buffer processing thread. This will move the perf impact of the string format out of the search thread.
• We implement HR timestamps as the default, and allow it to be "disabled" via a configuration.

Initial patch for evaluation. Not a complete implementation.
0001-Ticket-47982-improve-timestamp-resolution-in-logs.patch

We are using clock_gettime because it supports nanosecond resolution? If we assume that we only care about microsecond resolution, does it gain us anything to use gettimeofday() instead? Which one is more portable? Do either of them require hardware and/or kernel support?

The main note is:

"SVr4, 4.3BSD. POSIX.1-2001 describes gettimeofday() but not settimeofday(). POSIX.1-2008 marks gettimeofday() as obsolete, recommending the use of clock_gettime(2) instead. "

No special hardware is needed, but kernel support greater than 2.6.18 is needed as I understand it for linux.

Note, that in my code, I did detect HAVE_CLOCK_GETTIME, so that platforms that have not implemented the posix.1-2008 standard, will still function correctly.

Since it is an "Initial patch for evaluation", this type of review may not be required yet...

But here's a few thoughts.

Since the log functions are called frequently, you may not want to allocate this type of fixed size memory every time. You could just use the local space on the stack? (malloc+free is slower and causes memory fragmentation...)
{{{
2246 struct timespec *tsnow = malloc(sizeof(struct timespec));
}}}

Not sure about this default value... Aren't there any tools/utilities that could depend upon the format? In our package, logconv has no impact?
{{{
1629 #ifdef HAVE_CLOCK_GETTIME
1630 init_logging_hr_timestamps =
1631 cfg->logging_hr_timestamps = LDAP_ON;
1632 #endif
}}}

Replying to [comment:12 nhosoi]:

Since it is an "Initial patch for evaluation", this type of review may not be required yet...

But here's a few thoughts.

These are exactly the kind of comments I wanted!

Since the log functions are called frequently, you may not want to allocate this type of fixed size memory every time. You could just use the local space on the stack? (malloc+free is slower and causes memory fragmentation...)
{{{
2246 struct timespec *tsnow = malloc(sizeof(struct timespec));
}}}

That is a good point. I will change that for the next revision.

Not sure about this default value... Aren't there any tools/utilities that could depend upon the format? In our package, logconv has no impact?
{{{
1629 #ifdef HAVE_CLOCK_GETTIME
1630 init_logging_hr_timestamps =
1631 cfg->logging_hr_timestamps = LDAP_ON;
1632 #endif
}}}

There are tools that depend on this format, but I planned to update them also as part of this change.

I think having it as default makes more sense, and allowing people to turn it off if they require the less precise timestamps (Rather, the old format).

All right. If you are aware of any tools depending on the current time format, could you please open a ticket for them? Thanks!!

Add support for HR timestamps in logconv.pl
0001-Ticket-47982-improve-timestamp-resolution-in-logs.2.patch

William, thank you for adding the nano sec format support to logconv. I like your idea to automatically support with and without the nanosecond part.

The patch might be still in the "Initial patch for evaluation" mode, though... I still see malloc in the patch. If you want to keep it, please use slapi_ch_malloc/calloc/realloc for malloc. And slapi_ch_free/free_string.
{{{
2244 struct timespec tsnow = malloc(sizeof(struct timespec));
2245 if (clock_gettime(CLOCK_REALTIME, tsnow) != 0) {
2246 / Make error /
2247 }
2248 / We would probably check the HR timer boolean here /
2249 if (format_localTime_hr_log(tsnow->tv_sec, tsnow->tv_nsec, SLAPI_LOG_BUFSIZ, buffer, &blen) != 0) {
2250 / Make error - But's it's not like we had any handling before */
2251 }
2252 free(tsnow);
}}}

Error handling added and tested.
0001-Ticket-47982-improve-timestamp-resolution-in-logs.3.patch

Okay, so the last question is now, do we want to ditch the string format cache? Or do we want to keep it? We gain performance by getting rid of it. I vote to remove it.

Replying to [comment:16 firstyear]:

Okay, so the last question is now, do we want to ditch the string format cache? Or do we want to keep it? We gain performance by getting rid of it. I vote to remove it.
If it does not add any benefit (rather harm...?), +1 to "remove".

In that case, it's review time.

Replying to [comment:18 firstyear]:

In that case, it's review time.

Do you have a plan to clean up the code? E.g., ...
/ if (format_localTime_cached_log(tnl, SLAPI_LOG_BUFSIZ, buffer, &blen) != 0) { /

Once I got the "review ack" and everyone was happy with me getting rid of the cached version, yes. I was also going to comment out the implementation of format_localTime_cached_log and format_localTime_hr_cached_log.

Is that okay?

Well, we usually review the final version... If you are planing to modify the patch later, the "ack" flag is not supposed to be set.

Of course, reviewing the current patch as a tentative one works for me. Please clarify it in the review request email. Thanks!

On 03/02/2016 07:04 PM, William Brown wrote:

To clarify, there is still some code cleanup to do: This is just the "final"
implementation without cache, and with HR by default.

The "final" implementation looks good to me.

This is just a coding style, but when you pass the length to the "snprintf" type function, instead of giving the macro SLAPI_LOG_BUFSIZ, you could give sizeof(vbuf). This way, someone change the size of vbuf to something else in the future, we have less chance to add a bug as well as less effort to change all the lines that use SLAPI_LOG_BUFSIZ... (Note: there are other similar codes...)
{{{
2396 2421 char vbuf[SLAPI_LOG_BUFSIZ];
2439 2427 vlen = PR_vsnprintf(vbuf, SLAPI_LOG_BUFSIZ, fmt, ap);
}}}

Not to forget to include these in the code cleanup...
{{{
static PRLock ts_time_lock = NULL;
static PRLock ts_time_hr_lock = NULL;

define NSEC_TOLERANCE 800000000

etc.
}}}

Final cleanup
0001-Ticket-47982-improve-timestamp-resolution-in-logs.4.patch

Change the snprintf to have sizeof(buffer) calls. Removed un-needed functions, constants and header bits.

Should be good to go at this point. I've done a shakedown test already and it looks good to me under load.

Thanks for the updates. Acked.

commit 0aaf4dcd9232376544addad2cff06fd50227ddd9

To ssh://git.fedorahosted.org/git/389/ds.git
5d975ea..dbf1699 master -> master

Reopening, there is a regression with this fix. Its removes the subsystem logging:

Before:

[24/Mar/2016:04:35:13 -0400] NSMMReplicationPlugin - agmt="cn=to ReplD" (localhost:7777): State: backoff -> backoff

After:
:\
[24/Mar/2016:08:32:36.925620445 -0400] agmt="cn=to ReplB" (localhost:5555): State: start -> ready_to_acquire_replica

Note the missing subsytem: NSMMReplicationPlugin

attachment
0001-Ticket-47982-HR-Log-timers-regression-fix-for-subsys.patch

Fix for regression as notice by MReynolds.

{{{
[30/Mar/2016:13:03:51.001200746 +1000] 389-Directory/1.3.5.1 B2016.090.32 starting up
[30/Mar/2016:13:03:51.313443525 +1000] convert_pbe_des_to_aes: Checking for DES passwords to convert to AES...
[30/Mar/2016:13:03:51.326874144 +1000] convert_pbe_des_to_aes - No DES passwords found to convert.
[30/Mar/2016:13:03:51.338278055 +1000] slapd started. Listening on All Interfaces port 389 for LDAP requests
}}}

Note the correct subsystem listed for convert_pbe_des_to_aes.

Thanks William!

commit 90df4c4070d45329cf112627c86d6b0e62d21df4
Total 6 (delta 4), reused 0 (delta 0)
To ssh://git.fedorahosted.org/git/389/ds.git
696e29b..6858dfd master -> master

attachment
0001-Ticket-47982-Fix-log-hr-timestamps-when-invalid-valu.patch

commit 4182268
Compressing objects: 100% (6/6), done.
Writing objects: 100% (6/6), 866 bytes | 0 bytes/s, done.
Total 6 (delta 4), reused 0 (delta 0)
To ssh://git.fedorahosted.org/git/389/ds.git
f4cfadb..4182268 master -> master

CI test for this fix
0001-Ticket-47982-Add-CI-test-suite-ds_logs.patch

Test looks great to me thanks. Do you want me to apply the patch?

To ssh://git.fedorahosted.org/git/389/ds.git
20d7abb..4973699 master -> master
commit 4973699
Author: Amita Sharma amsharma@redhat.com
Date: Fri Dec 9 19:21:39 2016 +0530

389-ds-base is moving from Pagure to Github. This means that new issues and pull requests
will be accepted only in 389-ds-base's github repository.

This issue has been cloned to Github and is available here:
- https://github.com/389ds/389-ds-base/issues/1313

If you want to receive further updates on the issue, please navigate to the github issue
and click on subscribe button.

Thank you for understanding. We apologize for all inconvenience.