Page 1 of 2 12 LastLast
Results 1 to 10 of 12

Thread: journalctl slow response time...

  1. #1
    Join Date
    Apr 2013
    Location
    Houston, TX
    Posts
    10

    Default journalctl slow response time...

    Hello,

    After several searches of the forums I could not find an answer. I would appreciate any assistance or point me in the right direction if this has already been solved/answered. I apologize if this is a lot of information I tried to be very detailed.

    Quick Information:


    openSUSE version you are working on -> openSUSE 13.2 (Tumbleweed Repositories)
    the name and the version number of the application that you believe is giving you problems -> journalctl (systemd 210)
    an appropriate description of the symptoms -> journalctl slow response time.

    Background Details:


    Many, Many years ago (geeze, now I feel old). I setup ssh to only Allow one user into server by setting the AllowUsers option; I then wrote a perl script which monitored the /var/log/messages file for ssh brute force login attempts. It would pull out the IP address of the attempted login and then would DROP the IP address with a call to iptables. The script was really simple and searching the /var/log/messages file ran very fast (less than a second) it looks something like:

    Code:
    open(MESSAGES, '/usr/bin/tail -f /var/log/messages |');
    
    while(<MESSAGES>)
    {       
            chomp();
            
            if((/Invalid user/                                ||
                /allowed because not listed in AllowUsers/    ||
                /but this does not map back to the addres/)   &&
              (/\b(\d{1,3}(?:\.\d{1,3}){3})\b/)) { block_punk($1); }
    }
    The Problem:

    After recently upgrading to openSUSE 13.2 I noticed my simple little script started to fail miserably. I did some googling and quickly found that /var/log/messages no longer exists and I should now use journalctl. OK, I can deal with change and adjusted my script to:

    Code:
    open(MESSAGES, '/usr/bin/journalctl -f -u sshd |');  // OpenSuse 13.2 journalctl change
    
    while(<MESSAGES>)
    {       
            chomp();
            
            if((/Invalid user/                                ||
                /allowed because not listed in AllowUsers/    ||
                /but this does not map back to the addres/)   &&
              (/\b(\d{1,3}(?:\.\d{1,3}){3})\b/)) { block_punk($1); }
    }
    This now runs but what I noticed is that pulling records from the journal is very slow. I pulled out the new call to journalctl and ran it on the command line; for example when running this command directly:

    Code:
    time journalctl -u sshd |tail -100
    I get the results of:

    Code:
    real    1m28.185s
    user    1m5.448s
    sys     0m28.105s
    So it is taking 1 minute 28 seconds to pull the last 100 sshd log entries out of the journal.

    And Now Finally A Question:

    I appreciate you making it this far. Can you please tell me why journalctl is running so slow?

    Thanks For You Patience,

    Jim

    P.S. Just one more thing. I know there are plenty of ways to prevent brute force ssh attacks (fail2ban, Sshguard, Denyhosts, etc.) and I know I can re-enebale syslog-ng or rsyslog to resolve the issue. But what I really want to know is what is up with journalctl being so slow?

  2. #2
    Join Date
    May 2012
    Location
    Finland
    Posts
    2,004

    Default Re: journalctl slow response time...

    You don't NEED to use journalctl, you can install (for example) rsyslog, start it, enable it to startup and you'll have a /var/log/messages again.

    So in essence;
    zypper in rsyslog
    systemctl enable rsyslog
    systemctl start rsyslog

    Boom you're done I personally use this over journalctl for simplicity.
    .: miuku #suse @ irc.freenode.net
    :: miuku@opensuse.org

    .: h​ttps://download.opensuse.org/repositories/home:/Miuku/

  3. #3
    Join Date
    Feb 2009
    Location
    Spain
    Posts
    25,547

    Default Re: journalctl slow response time...

    On 2014-12-21 19:06, JimOpensuse wrote:


    Code:
    
    >   open(MESSAGES, '/usr/bin/tail -f /var/log/messages |');
    You should use "tailf" instead, which doesn't cause disk activity if
    there is no new data.




    > _And_Now_Finally_A_Question:
    > _
    > I appreciate you making it this far. *- Can you please tell me why
    > journalctl is running so slow?-*


    IMO, bad design, plain and simple.

    The designers were using SSD devices, which are specially fast on seek
    as compared to rotating hard disks. When normal people use it they find
    it slow, but the devs answer is to buy an SSD (no kidding, we got that
    answer in the mail list).

    The basic reason is that it is an on-disk database, heavily fragmented.
    Reading it makes the disk head jump all over the place.

    You could try "dmesg --follow" instead.

    --
    Cheers / Saludos,

    Carlos E. R.
    (from 13.1 x86_64 "Bottle" at Telcontar)

  4. #4
    Join Date
    Jun 2008
    Location
    San Diego, Ca, USA
    Posts
    11,109
    Blog Entries
    2

    Default Re: journalctl slow response time...

    From time to time I see these posts about slow times parsing journalctl, but I wonder why I haven't seen them (so can't really speculate on a cause)

    So, for example on one of my systems
    Code:
    time journalctl -u sshd | tail -100-- Logs begin at Sat 2014-11-15 16:36:51 PST, end at Sun 2014-12-21 20:55:35 PST. --
    
    
    real	0m1.468s
    user	0m0.000s
    sys	0m0.026s
    I don't know that I would blame disk defragmentation, the amount of data that's parsed is really tiny (only last 100 entries). I wonder if system resources might be committed elsewhere... So, for instance I'd look at

    Committed RAM to buffers and available free by using the Free tool
    https://en.opensuse.org/User:Tsu2/free_tool
    Note: Is this happening only on machines which have been running for a long while? If so, my above article contains a command to free committed RAM. You'd have to weigh the upside (faster overall system response after heavy taskloads) vs the downside (slower re-invoking previous heavy taskloads).

    Reading process activity in realtime with a "top" console already open.

    Reading disk activity in realtime (sensors?). You might see whether disk activity is immediate when your command runs or if as I suspect there is no change in activity for a long while and only just before your results are returned and displayed.

    TSU

  5. #5
    Join Date
    Apr 2013
    Location
    Houston, TX
    Posts
    10

    Default Re: journalctl slow response time...

    Thank you very much for the information Miuku!

    I will certainly look into that.

    I was really however trying to figure out what was going on with journalctl.

    Quote Originally Posted by Miuku View Post
    You don't NEED to use journalctl, you can install (for example) rsyslog, start it, enable it to startup and you'll have a /var/log/messages again.

    So in essence;
    zypper in rsyslog
    systemctl enable rsyslog
    systemctl start rsyslog

    Boom you're done I personally use this over journalctl for simplicity.

  6. #6
    Join Date
    Apr 2013
    Location
    Houston, TX
    Posts
    10

    Default Re: journalctl slow response time...

    Thanks for the information Carlos!

    The great thing about Linux is that I learn something new all the time (Your tailf suggestion is great, I was not aware of that one)

    in regards to the journalctl, I am actually running with SSDs and have lots of free RAM:
    Code:
    jim@slacker:~> free
                 total       used       free     shared    buffers     cached
    Mem:      32906756   19671536   13235220      38876     942384   15629576
    -/+ buffers/cache:    3099576   29807180
    Swap:      8400892          0    8400892
    I will continue to play with it.

    Thanks Again....

    Quote Originally Posted by robin_listas View Post
    On 2014-12-21 19:06, JimOpensuse wrote:


    Code:
    
    >   open(MESSAGES, '/usr/bin/tail -f /var/log/messages |');
    You should use "tailf" instead, which doesn't cause disk activity if
    there is no new data.




    > _And_Now_Finally_A_Question:
    > _
    > I appreciate you making it this far. *- Can you please tell me why
    > journalctl is running so slow?-*


    IMO, bad design, plain and simple.

    The designers were using SSD devices, which are specially fast on seek
    as compared to rotating hard disks. When normal people use it they find
    it slow, but the devs answer is to buy an SSD (no kidding, we got that
    answer in the mail list).

    The basic reason is that it is an on-disk database, heavily fragmented.
    Reading it makes the disk head jump all over the place.

    You could try "dmesg --follow" instead.

    --
    Cheers / Saludos,

    Carlos E. R.
    (from 13.1 x86_64 "Bottle" at Telcontar)

  7. #7
    Join Date
    Feb 2009
    Location
    Spain
    Posts
    25,547

    Default Re: journalctl slow response time...

    On 2014-12-23 05:16, JimOpensuse wrote:
    >
    > Thanks for the information Carlos!
    >
    > The great thing about Linux is that I learn something new all the time
    > (-Your tailf suggestion is great, I was not aware of that one-)
    >
    > in regards to the journalctl, I am actually running with SSDs and have
    > lots of free RAM:


    In that case, its processing should be fast.

    Try with dmesg instead...

    Or...

    With syslog, you can place hooks in syslog itself so that instead of you
    reading the logs watching for some entries, the syslog daemon calls you
    when he, that is already reading the logs, sees an entry that you told
    him you are interested in.

    Meaning that you can call code when a certain message appears, directly
    from syslog.

    I'm not aware of the systemd journal having a similar capability, but it
    should.

    --
    Cheers / Saludos,

    Carlos E. R.
    (from 13.1 x86_64 "Bottle" at Telcontar)

  8. #8
    Join Date
    Feb 2009
    Location
    Spain
    Posts
    25,547

    Default Re: journalctl slow response time...

    On 2014-12-22 19:16, tsu2 wrote:
    >
    > From time to time I see these posts about slow times parsing journalctl,
    > but I wonder why I haven't seen them (so can't really speculate on a
    > cause)


    It happens when the persistent storage on rotating hard disk is large.

    --
    Cheers / Saludos,

    Carlos E. R.
    (from 13.1 x86_64 "Bottle" at Telcontar)

  9. #9
    Join Date
    Jun 2008
    Location
    San Diego, Ca, USA
    Posts
    11,109
    Blog Entries
    2

    Default Re: journalctl slow response time...

    Quote Originally Posted by robin_listas View Post
    On 2014-12-22 19:16, tsu2 wrote:
    >
    > From time to time I see these posts about slow times parsing journalctl,
    > but I wonder why I haven't seen them (so can't really speculate on a
    > cause)


    It happens when the persistent storage on rotating hard disk is large.

    --
    Cheers / Saludos,

    Carlos E. R.
    (from 13.1 x86_64 "Bottle" at Telcontar)
    OK,
    So, out of curiosity I did a little Internet digging...

    First, an original discussion in 2012 when a "slow journalctl" was observed. Note Linus Poettering's comments in the thread. Less important are the specific problems with that journalctl since today's versions have switches which address some of those issues(and there may be code changes)... perhaps most importantly the ability to view data "newest entry first"
    https://bugzilla.redhat.com/show_bug.cgi?id=867841

    But in general the various Internet postings about slowness have been about journal files several hundred megabytes in size. Mine certainly aren't. You may need to check whether yours is still <100MB as well.
    Example, this thread
    https://bbs.archlinux.org/viewtopic.php?id=153922
    Checking log size and fragmentation
    http://upalmin.blogspot.com/2014/01/blog-post.html

    More likely seems to be journal corruption. You can output errors in your journal with the following
    Code:
    journalctl --verify
    The problem is that identifying journal corruption still leaves with you with limited options... You can delete your logs but there seems to be almost no way to know how they became corrupted and how to prevent it from happening again in the future.

    Although there are some postings about slowness on btfrs, nothing specific was pinned down. So, absent some btfrs-specific discovery it's not likely relevant and the above (<extreme> size and file corruption) are possibly more likely causes.

    Lastly,
    You'll notice the references I posted are a couple years old. It may only be a limitation of my Googling, but I found <very> few postings about a slow journalctl after 2012.

    TSU

  10. #10
    Join Date
    Feb 2009
    Location
    Spain
    Posts
    25,547

    Default Re: journalctl slow response time...

    On 2014-12-24 19:06, tsu2 wrote:
    >
    > robin_listas;2684805 Wrote:



    >> It happens when the persistent storage on rotating hard disk is large.


    > OK,
    > So, out of curiosity I did a little Internet digging...


    My recollections are of openSUSE mail list, mostly. For instance, I see
    one comment Nov 2013, grepping for "slow" and "journalctl" in the same
    email.

    BTW journalctl is terrible slow. For example
    journalctl --full
    would take a few hours (or days) I guess.

    But there was a long and angry thread that I can not locate.

    There are other comments mentioning that there are tools for verifying
    the journal, but none for repair, and that it was not planned to create
    one (2013).

    I can not do any testing myself, because I use syslog instead for long
    term logs; I only allow systemd to keep the journal of the current
    session, and even then it is big:

    Code:
    Telcontar:~ # journalctl --disk-usage
    Journals take up 408.3M on disk.
    Telcontar:~ #
    
    cer@Telcontar:~> uptime
    15:27  up 12 days 18:55,  72 users,  load average: 0,83, 0,57, 0,60
    cer@Telcontar:~>
    
    Telcontar:~ # time journalctl > logs
    
    real    1m14.254s
    user    0m9.986s
    sys     0m2.741s
    Telcontar:~ # ls -lh logs
    -rw-r--r-- 1 root root 44M Dec 25 15:28 logs
    Telcontar:~ #
    A second run is faster:

    Telcontar:~ # time journalctl -l > logs

    Code:
    real    0m11.065s
    user    0m9.680s
    sys     0m1.372s
    Telcontar:~ # ls -lh logs
    -rw-r--r-- 1 root root 44M Dec 25 15:31 logs
    Telcontar:~ #
    which indicates that the main time factor is the hard disk reading. If I
    had my 2 year log in the journal, it would be terribly big and slow
    (consider: mine has 400 MB in 12 days).

    Still the text dump is an order of magnitude smaller than the journal.



    --
    Cheers / Saludos,

    Carlos E. R.
    (from 13.1 x86_64 "Bottle" at Telcontar)

Page 1 of 2 12 LastLast

Tags for this Thread

Posting Permissions

  • You may not post new threads
  • You may not post replies
  • You may not post attachments
  • You may not edit your posts
  •