Home of the Squeezebox™ & Transporter® network music players.
Results 1 to 9 of 9
  1. #1

    Slow web interface, probably after Perl updates

    Logitech Media Server Version: 8.2.1 - 1628483320 @ Mon Aug 9 06:43:27 CEST 2021

    Operating system: Debian - EN - iso-8859-1
    Platform Architecture: x86_64-linux
    Perl Version: 5.32.1 - x86_64-linux-gnu-thread-multi
    Audio::Scan: 1.02
    IO::Socket::SSL: 2.074
    Database Version: DBD::SQLite 1.58 (sqlite 3.22.0)
    Total Players Recognized: 4

    After a restart I have noticed that the LMS web interface has become incredibly slow, taking multiple seconds to respond to inputs. Starting it with:

    sudo -u squeezeboxserver squeezeboxserver --perfwarn=1

    a lot of this is logged - almost always about 10s which suggests something is waiting 10s, then doing it's thing:

    Code:
    [22-01-17 22:24:42.8066] Logging Async HTTP   >  1.00000s
    [22-01-17 22:24:42.8067] Logging Request      >  1.00000s
    [22-01-17 22:24:42.8068] Logging Notify       >  1.00000s
    [22-01-17 22:24:42.8069] Logging IR Delay     >  1.00000s
    [22-01-17 22:24:42.8070] Logging DB Access    >  1.00000s
    [22-01-17 22:24:42.8071] Logging AnyEvent CB  >  1.00000s
    [22-01-17 22:24:42.8071] Logging Template     >  1.00000s
    [22-01-17 22:24:42.8072] Logging Scheduler    >  1.00000s
    [22-01-17 22:24:42.8073] Logging Timer        >  1.00000s
    [22-01-17 22:24:42.8074] Logging IO           >  1.00000s
    [22-01-17 22:24:42.8074] Logging Page Build   >  1.00000s
    [22-01-17 22:24:56.4551] IO          10.00867 : Slim::Web::HTTP::processHTTP
    [22-01-17 22:25:06.6097] IO          10.00755 : Slim::Web::HTTP::processHTTP
    [22-01-17 22:25:16.7495] IO          10.00951 : Slim::Web::HTTP::processHTTP
    [22-01-17 22:25:26.8576] IO          10.00694 : Slim::Web::HTTP::processHTTP
    [22-01-17 22:25:36.9815] IO          10.00994 : Slim::Web::HTTP::processHTTP
    [22-01-17 22:25:47.0934] IO          10.00940 : Slim::Web::HTTP::processHTTP
    [22-01-17 22:25:57.2891] IO          10.01004 : Slim::Web::HTTP::processHTTP
    [22-01-17 22:26:07.3976] IO          10.00811 : Slim::Web::HTTP::processHTTP
    [22-01-17 22:26:17.5056] IO          10.00714 : Slim::Web::HTTP::processHTTP
    [22-01-17 22:26:27.6154] IO          10.00901 : Slim::Web::HTTP::processHTTP
    [22-01-17 22:26:37.7257] IO          10.00943 : Slim::Web::HTTP::processHTTP
    [22-01-17 22:26:47.8360] IO          10.00960 : Slim::Web::HTTP::processHTTP
    [22-01-17 22:26:57.9455] IO          10.00870 : Slim::Web::HTTP::processHTTP
    [22-01-17 22:27:08.0564] IO          10.00993 : Slim::Web::HTTP::processHTTP
    [22-01-17 22:27:18.1655] IO          10.00849 : Slim::Web::HTTP::processHTTP
    [22-01-17 22:27:28.2735] IO          10.00694 : Slim::Web::HTTP::processHTTP
    [22-01-17 22:27:38.3815] IO          10.00723 : Slim::Web::HTTP::processHTTP
    [22-01-17 22:27:48.4894] IO          10.00700 : Slim::Web::HTTP::processHTTP
    This matches up with the Network tab in Web Developer Tools, looks like 10s for each request to be served.



    These are the Perl packages I updated recently:
    Code:
    2022-01-05 19:48:08 status installed libfile-stripnondeterminism-perl:all 1.13.0-1
    2022-01-05 19:48:12 status installed libwww-perl:all 6.60-1
    2022-01-05 19:48:22 status installed libdebhelper-perl:all 13.6
    2022-01-05 19:48:23 status installed libnet-dns-perl:all 1.33-1
    2022-01-05 19:48:24 status installed libimage-exiftool-perl:all 12.38+dfsg-1
    2022-01-05 19:48:42 status installed libdbd-sqlite3-perl:amd64 1.70-3
    2022-01-05 19:49:07 status installed libio-socket-ssl-perl:all 2.073-1
    2022-01-05 19:49:07 status installed libdatetime-perl:amd64 2:1.55-1
    2022-01-08 14:33:09 status installed libhttp-message-perl:all 6.36-1
    2022-01-15 20:08:25 status installed libnet-ssleay-perl:amd64 1.92-1
    2022-01-15 20:08:51 status installed libxml-libxml-perl:amd64 2.0207+dfsg-2
    2022-01-15 20:08:54 status installed libcrypt-openssl-rsa-perl:amd64 0.32-2
    2022-01-15 20:08:54 status installed libmro-compat-perl:all 0.15-1
    2022-01-15 20:08:57 status installed libio-socket-ssl-perl:all 2.074-2
    2022-01-15 20:08:57 status installed libfile-mimeinfo-perl:all 0.31-1
    I suspect the most recent batch is the culprit, although I am not sure.

  2. #2
    Babelfish's Best Boy mherger's Avatar
    Join Date
    Apr 2005
    Location
    Switzerland
    Posts
    20,716

    Slow web interface,probably after Perl updates

    > [22-01-17 22:24:56.4551] IO 10.00867 : Slim::Web::HTTP:rocessHTTP
    > [22-01-17 22:25:06.6097] IO 10.00755 : Slim::Web::HTTP:rocessHTTP
    > [22-01-17 22:25:16.7495] IO 10.00951 : Slim::Web::HTTP:rocessHTTP
    > [22-01-17 22:25:26.8576] IO 10.00694 : Slim::Web::HTTP:rocessHTTP
    > [22-01-17 22:25:36.9815] IO 10.00994 : Slim::Web::HTTP:rocessHTTP
    > [22-01-17 22:25:47.0934] IO 10.00940 : Slim::Web::HTTP:rocessHTTP
    > [22-01-17 22:25:57.2891] IO 10.01004 : Slim::Web::HTTP:rocessHTTP
    > [22-01-17 22:26:07.3976] IO 10.00811 : Slim::Web::HTTP:rocessHTTP
    > [22-01-17 22:26:17.5056] IO 10.00714 : Slim::Web::HTTP:rocessHTTP
    > [22-01-17 22:26:27.6154] IO 10.00901 : Slim::Web::HTTP:rocessHTTP
    > [22-01-17 22:26:37.7257] IO 10.00943 : Slim::Web::HTTP:rocessHTTP
    > [22-01-17 22:26:47.8360] IO 10.00960 : Slim::Web::HTTP:rocessHTTP
    > [22-01-17 22:26:57.9455] IO 10.00870 : Slim::Web::HTTP:rocessHTTP
    > [22-01-17 22:27:08.0564] IO 10.00993 : Slim::Web::HTTP:rocessHTTP
    > [22-01-17 22:27:18.1655] IO 10.00849 : Slim::Web::HTTP:rocessHTTP
    > [22-01-17 22:27:28.2735] IO 10.00694 : Slim::Web::HTTP:rocessHTTP
    > [22-01-17 22:27:38.3815] IO 10.00723 : Slim::Web::HTTP:rocessHTTP
    > [22-01-17 22:27:48.4894] IO 10.00700 : Slim::Web::HTTP:rocessHTTP


    Hmm... these are all so close to 10s, I'm wondering whether it's some
    kind of timeout somewhere. Nothing interesting in server.log?

  3. #3
    Senior Member
    Join Date
    Dec 2020
    Posts
    256
    Sounds like a DNS timeout. Possibly the updated module (Net:NS - libnet-dns-perl) is more strict about some misconfiguration on your machine.

  4. #4
    I have tested with dig and nslookup every DNS query I can think of that LMS might be making in this case - the IP of the client, the IP of a player, the server's own name and it's own IP. The response time is very much less than 10s. I am running bind on the server itself so it doesn't need to try the internet for anything internal.
    I don't know why it would be trying to resolve something on the internet, so don't know what queries to test there.
    Is there a log level for LMS that would print DNS queries?
    I will try and write a simple DNS lookup script using Net:NS to see if that behaves properly.

  5. #5
    Tested DNS with the first example, works fine, no delays.
    https://metacpan.org/pod/Net:NS#EXAMPLES

  6. #6
    Babelfish's Best Boy mherger's Avatar
    Join Date
    Apr 2005
    Location
    Switzerland
    Posts
    20,716

    Slow web interface,probably after Perl updates

    Not sure yet what this is. But could you please re-run the perfmon log
    check _without_ playing any music? Would you still see those entries?
    Are you using DLNA clients?

  7. #7
    This is driving me crazy....it has stopped logging these events at 2242 when I got bored of messing with it and went to bed. Checked web interface and it's fine. Restarted LMS, still fine. This is so annoying! I hadn't actually tried the web interface this morning when I was testing DNS resolution.

    Code:
    [22-01-18 22:41:03.7535] IO          10.00685 : Slim::Web::HTTP::processHTTP
    [22-01-18 22:41:13.8640] IO          10.00965 : Slim::Web::HTTP::processHTTP
    [22-01-18 22:41:23.9735] IO          10.00883 : Slim::Web::HTTP::processHTTP
    [22-01-18 22:41:34.0826] IO          10.00793 : Slim::Web::HTTP::processHTTP
    [22-01-18 22:41:44.1895] IO          10.00645 : Slim::Web::HTTP::processHTTP
    [22-01-18 22:41:54.2975] IO          10.00698 : Slim::Web::HTTP::processHTTP
    [22-01-18 22:42:04.4055] IO          10.00706 : Slim::Web::HTTP::processHTTP
    [22-01-19 15:54:38.7656] Logging Template     >  1.00000s
    [22-01-19 15:54:38.7665] Logging Page Build   >  1.00000s
    [22-01-19 15:54:38.7666] Logging AnyEvent CB  >  1.00000s
    [22-01-19 15:54:38.7667] Logging Async HTTP   >  1.00000s
    [22-01-19 15:54:38.7668] Logging Request      >  1.00000s
    [22-01-19 15:54:38.7669] Logging IR Delay     >  1.00000s
    [22-01-19 15:54:38.7670] Logging IO           >  1.00000s
    [22-01-19 15:54:38.7671] Logging Notify       >  1.00000s
    [22-01-19 15:54:38.7672] Logging Timer        >  1.00000s
    [22-01-19 15:54:38.7672] Logging Scheduler    >  1.00000s
    [22-01-19 15:54:38.7673] Logging DB Access    >  1.00000s

    Not using DLNA clients.

  8. #8
    Senior Member
    Join Date
    Dec 2020
    Posts
    256
    Bind? Are you managing a network for a large multinational?

    Just kidding, if you managed to get the fundamentals of it and it works, it works. Would never recommend it to any home user though. Either way, the reason for me to suspect DNS is that the default settings for resolvconf is a timeout of five seconds and two retries, which adds to a total of ten seconds. Hard to tell what it might have been when it spontaneously resolved itself.

  9. #9

    [Solved] Slow web interface, if you hammer it with requests

    Turns out, I am not going crazy. The culprit for this seems to be my desktop PC. I am using my work laptop during the day and desktop PC in the evening. So the problem went away when I shut my desktop down last night and I couldn't see the problem during the day. Turn my desktop on and the messages start again:

    Code:
    [22-01-19 21:15:08.2839] IO          10.03416 : Slim::Web::HTTP::processHTTP
    [22-01-19 21:15:18.3988] IO          10.00898 : Slim::Web::HTTP::processHTTP
    [22-01-19 21:15:28.5075] IO          10.00832 : Slim::Web::HTTP::processHTTP
    [22-01-19 21:15:38.6196] IO          10.00981 : Slim::Web::HTTP::processHTTP
    Kill squeezelite on my desktop, messages stop.
    Now promise you won't laugh....I was running it with -s 192.168.1.3:9000 after reading a comment on this bug when I was trying to troubleshoot something else:

    https://github.com/ralph-irving/sque...ment-968386878

    All this does is hammer the LMS web interface with connection attempts, hence the terrible performance. It "fixes" the "player already active" messages because it's not really connected, 9000 being the wrong port. It seems like you can pass any port number at all to Squeezelite and it doesn't give you any feedback that it couldn't connect!

Posting Permissions

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