Chris Murphy <lists@xxxxxxxxxxxxxxxxx> writes:
> Yeah I don't know any details about this hook; but basically
> systemd-journald is the single source for logging now, but it provides
> a socket for rsyslog (and other conventional loggers that have been
> updated) can grab the stream and do their own thing like they have in
> the past. But there is only one such socket, and no two loggers can
> share it, as I understand things.
Thanks for the background.
I think I have a handle on what was happening. The delay wasn't in the
input side of things but in my using the stdout/stderr to do a quick and
dirty logging via systemd's redirection of stdout/stderr into the logs.
Systemd seems to delay things a bit more as time goes on. Maybe a delay
based on the total byte-count as some auto-adjusting efficiency hack?
In any case this shell script with the output to a gnome terminal showed
only 3 or 4 milliseconds delay over a 24+ hr period.
journalctl -f -o short-precise -u apcupsd | \
while read line
do
date="$(date '+%b %d %H:%M:%S.%N')"
echo "$date -- $line"
done
Feb 12 17:32:50.127051639 -- Feb 12 17:32:50.124113 arbol.wsrcc.com apcupsd[1147]: 000.0,000.0,000.0,27.27,00.00,29.0,00.0,000.0,000.0,119.0,100.0,1
Feb 12 17:33:50.615503948 -- Feb 12 17:33:50.610058 arbol.wsrcc.com apcupsd[1147]: 000.0,000.0,000.0,27.27,00.00,29.0,00.0,000.0,000.0,119.0,100.0,0
Feb 12 17:35:04.240717368 -- Feb 12 17:35:04.237443 arbol.wsrcc.com apcupsd[1147]: 000.0,000.0,000.0,27.27,00.00,29.0,00.0,000.0,000.0,119.0,100.0,1
Feb 12 17:36:57.216696271 -- Feb 12 17:36:57.213388 arbol.wsrcc.com apcupsd[1147]: 000.0,000.0,000.0,27.27,00.00,28.0,00.0,000.0,000.0,119.0,100.0,0
Feb 12 17:37:57.702263685 -- Feb 12 17:37:57.699308 arbol.wsrcc.com apcupsd[1147]: 000.0,000.0,000.0,27.27,00.00,28.0,00.0,000.0,000.0,119.0,100.0,1
Feb 12 17:38:58.198243702 -- Feb 12 17:38:58.185059 arbol.wsrcc.com apcupsd[1147]: 000.0,000.0,000.0,27.27,00.00,28.0,00.0,000.0,000.0,119.0,100.0,0
Feb 12 17:39:58.669490321 -- Feb 12 17:39:58.666990 arbol.wsrcc.com apcupsd[1147]: 000.0,000.0,000.0,27.27,00.00,28.0,00.0,000.0,000.0,119.0,100.0,1
Feb 12 17:40:59.152423114 -- Feb 12 17:40:59.148905 arbol.wsrcc.com apcupsd[1147]: 000.0,000.0,000.0,27.27,00.00,28.0,00.0,000.0,000.0,119.0,100.0,0
That ultra-low delay compared to what I was seeing got me wondering
about the delay in the output of my perl program.
Thanks for the ideas. Now that I replace the lazy logging in my perl
script with perl calls to syslog(), things are logging so rapidly that
the scripts log entries and sshd's log entries are interleaved. That's
never happened before.
> I think I have a below average handle on most Linux internals. I
> mostly just have a vivid imagination!
;-)
A good imagination is the most valuable debugging skill.
-wolfgang
--
users mailing list
users@xxxxxxxxxxxxxxxxxxxxxxx
To unsubscribe or change subscription options:
https://admin.fedoraproject.org/mailman/listinfo/users
Fedora Code of Conduct: http://fedoraproject.org/code-of-conduct
Guidelines: http://fedoraproject.org/wiki/Mailing_list_guidelines
Have a question? Ask away: http://ask.fedoraproject.org
