You are not logged in.

#1 2017-05-28 05:07:12

quequotion
Member
From: Oita, Japan
Registered: 2013-07-29
Posts: 620
Website

[SOLVED] org.cups.cupsd.service delays boot

This seems like an inordinate amout of time to start:

$ systemd-analyze blame | grep cups
          4.321s org.cups.cupsd.service

The biggest delay in it's chain is systemd-networkd.service, but 335ms seems fine:

$ systemd-analyze critical-chain org.cups.cupsd.service
The time after the unit is active or started is printed after the "@" character.
The time the unit takes to start is printed after the "+" character.

org.cups.cupsd.service +4.321s
└─network.target @9.787s
  └─systemd-networkd.service @9.451s +335ms
    └─dbus.service @7.845s
      └─basic.target @7.842s
        └─sockets.target @7.842s
          └─pcscd.socket @7.842s
            └─sysinit.target @7.812s
              └─systemd-timesyncd.service @7.690s +122ms
                └─systemd-tmpfiles-setup.service @7.557s +121ms
                  └─local-fs.target @7.556s
                    └─boot.mount @7.447s +109ms
                      └─dev-disk-by\x2duuid-552E\x2d4A68.device @7.418s

::EDIT:: The service logs nothing; status looks good:

$ systemctl status org.cups.cupsd.service
● org.cups.cupsd.service - CUPS Scheduler
   Loaded: loaded (/usr/lib/systemd/system/org.cups.cupsd.service; enabled; vendor preset: disabled)
   Active: active (running) since Sun 2017-05-28 13:47:28 JST; 15min ago
     Docs: man:cupsd(8)
 Main PID: 545 (cupsd)
   Status: "Scheduler is running..."
    Tasks: 5 (limit: 4915)
   CGroup: /system.slice/org.cups.cupsd.service
           ├─545 /usr/bin/cupsd -l
           ├─732 /usr/lib/cups/notifier/dbus dbus://
           ├─748 /usr/lib/cups/notifier/dbus dbus://
           └─749 /usr/lib/cups/notifier/dbus dbus://

In case you were curious, a full plot:
plot-sm.png

Last edited by quequotion (2017-06-25 00:08:38)

Offline

#2 2017-06-22 03:56:18

quequotion
Member
From: Oita, Japan
Registered: 2013-07-29
Posts: 620
Website

Re: [SOLVED] org.cups.cupsd.service delays boot

At first I thought it might be wasting time looking for my network connected printer, but it takes the same amount of time even if the printer is on and ready when the computer boots. Either it's still wasting time looking for other network connected printers or this has nothing to do with it.

Last edited by quequotion (2017-06-22 03:57:26)

Offline

#3 2017-06-22 04:00:27

jasonwryan
Anarchist
From: .nz
Registered: 2009-05-09
Posts: 25,035
Website

Re: [SOLVED] org.cups.cupsd.service delays boot

├─732 /usr/lib/cups/notifier/dbus dbus://
           ├─748 /usr/lib/cups/notifier/dbus dbus://
           └─749 /usr/lib/cups/notifier/dbus dbus://

What is that about? Neither of my boxes have those processes running. Is this related to your other thread?


Arch + dwm   •   Mercurial repos  •   Github

Registered Linux User #482438

Online

#4 2017-06-22 04:09:52

quequotion
Member
From: Oita, Japan
Registered: 2013-07-29
Posts: 620
Website

Re: [SOLVED] org.cups.cupsd.service delays boot

jasonwryan wrote:
├─732 /usr/lib/cups/notifier/dbus dbus://
           ├─748 /usr/lib/cups/notifier/dbus dbus://
           └─749 /usr/lib/cups/notifier/dbus dbus://

What is that about?

I have no idea at all.

EDIT again: I suspect they are something that only exists temporarily; ie to notify about a print job or cache jobs for a printer. Perhaps you would find them existing intermittently.

Is this related to your other thread?

No.

EDIT: I posted this thread a month ago; the service still takes too long to load on boot (4.111s on the last boot), but the extra dbus notifiers are not present at the moment:

● org.cups.cupsd.service - CUPS Scheduler
   Loaded: loaded (/usr/lib/systemd/system/org.cups.cupsd.service; disabled; vendor preset: disabled)
   Active: active (running) since Thu 2017-06-22 11:54:30 JST; 1h 20min ago
     Docs: man:cupsd(8)
 Main PID: 548 (cupsd)
   Status: "Scheduler is running..."
    Tasks: 2 (limit: 4915)
   CGroup: /system.slice/org.cups.cupsd.service
           └─548 /usr/bin/cupsd -l

In case you were curious, today's blame:

          4.790s dev-md126p2.device
          4.178s udisks2.service
          4.111s org.cups.cupsd.service
          2.597s polkit.service
          2.212s upower.service
          1.775s lm_sensors.service
          1.584s lightdm.service
          1.396s systemd-logind.service
          1.155s systemd-udevd.service
          1.089s systemd-tmpfiles-setup-dev.service
           960ms systemd-journald.service
           644ms systemd-modules-load.service
           578ms dev-hugepages.mount
           577ms dev-mqueue.mount
           530ms systemd-networkd.service
           509ms resume.swap
           456ms systemd-binfmt.service
           444ms accounts-daemon.service
           411ms sys-kernel-debug.mount
           356ms proc-sys-fs-binfmt_misc.mount
           333ms colord.service
           276ms systemd-udev-trigger.service
           274ms alsa-restore.service
           273ms systemd-tmpfiles-clean.service
           268ms systemd-random-seed.service
           192ms kmod-static-nodes.service
           189ms bluetooth.service
           174ms systemd-sysctl.service
           151ms systemd-timesyncd.service
           139ms systemd-tmpfiles-setup.service
           138ms systemd-remount-fs.service
           102ms systemd-localed.service
            94ms boot.mount
            86ms rtkit-daemon.service
            82ms systemd-journal-flush.service
            78ms systemd-hostnamed.service
            76ms user@1000.service
            46ms systemd-user-sessions.service
            37ms systemd-update-utmp.service
            27ms sys-kernel-config.mount
            12ms sys-fs-fuse-connections.mount
             1ms tmp.mount

EDIT again: Keep in mind this thread is for cups's service. dev-md126p2.device takes a long time setting up a the root partition, which is on a 4-disk RAID:0 and I don't expect it can do much better; udisks2.service is probably waiting for that and has several other devices to configure (another hard disk, an optical drive, multiple virtual devices on a card reader) so I don't expect it can be much faster either; in any case neither should have anything to do with org.cups.cupsd.service's sluggishness.

Last edited by quequotion (2017-07-23 00:07:24)

Offline

#5 2017-06-22 19:35:04

seth
Member
Registered: 2012-09-03
Posts: 7,208

Re: [SOLVED] org.cups.cupsd.service delays boot

Could it be that cups suffers from the same cause?
Can you try w/o the raid? Does it provide any path that could be relevant for cups?

Offline

#6 2017-06-23 00:06:43

quequotion
Member
From: Oita, Japan
Registered: 2013-07-29
Posts: 620
Website

Re: [SOLVED] org.cups.cupsd.service delays boot

seth wrote:

Can you try w/o the raid?

It is the root partition hmm

Does it provide any path that could be relevant for cups?

If loading files from the drive were a problem for cups, I feel like it would be a problem for everything else; like all the services would take much longer to load. To be honest, I do not know why this is not the case, but it does not seem to be the case (for everything else).

EDIT: There are these two disk-related services in its critical chain:

                    └─boot.mount @7.446s +228ms
                      └─dev-disk-by\x2duuid-552E\x2d4A68.device @7.434s

552E-4A68 is the UEFI boot partition, which is also on the raid device:

$ udevadm info /dev/disk/by-uuid/552E-4A68 
P: /devices/virtual/block/md126/md126p1
N: md126p1
L: 100
S: disk/by-id/md-uuid-959bead4:9ce389c6:6cf4caa1:71ffd6b2-part1
S: disk/by-uuid/552E-4A68
S: md/core_0p1
E: DEVLINKS=/dev/md/core_0p1 /dev/disk/by-id/md-uuid-959bead4:9ce389c6:6cf4caa1:71ffd6b2-part1 /dev/disk/by-uuid/552E-4A68
E: DEVNAME=/dev/md126p1
E: DEVPATH=/devices/virtual/block/md126/md126p1
E: DEVTYPE=partition
E: ID_FS_TYPE=vfat
E: ID_FS_USAGE=filesystem
E: ID_FS_UUID=552E-4A68
E: ID_FS_UUID_ENC=552E-4A68
E: ID_FS_VERSION=FAT32
E: ID_PART_ENTRY_DISK=9:126
E: ID_PART_ENTRY_NUMBER=1
E: ID_PART_ENTRY_OFFSET=2048
E: ID_PART_ENTRY_SCHEME=gpt
E: ID_PART_ENTRY_SIZE=999424
E: ID_PART_ENTRY_TYPE=c12a7328-f81f-11d2-ba4b-00a0c93ec93b
E: ID_PART_ENTRY_UUID=fa65eb50-0667-4593-b7f9-3971b0e0e578
E: MAJOR=259
E: MD_CONTAINER=/dev/md/imsm0
E: MD_DEVICES=4
E: MD_DEVICE_sda_DEV=/dev/sda
E: MD_DEVICE_sda_ROLE=0
E: MD_DEVICE_sdb_DEV=/dev/sdb
E: MD_DEVICE_sdb_ROLE=1
E: MD_DEVICE_sdc_DEV=/dev/sdc
E: MD_DEVICE_sdc_ROLE=2
E: MD_DEVICE_sdd_DEV=/dev/sdd
E: MD_DEVICE_sdd_ROLE=3
E: MD_DEVNAME=core_0
E: MD_LEVEL=raid0
E: MD_MEMBER=0
E: MD_UUID=959bead4:9ce389c6:6cf4caa1:71ffd6b2
E: MINOR=0
E: PARTN=1
E: SUBSYSTEM=block
E: TAGS=:systemd:
E: UDISKS_IGNORE=1
E: USEC_INITIALIZED=14998117

And in case you were curious, today's full critical-chain:

graphical.target @14.115s
└─multi-user.target @14.115s
  └─cups-browsed.service @14.115s
    └─org.cups.cupsd.service @9.955s +4.159s (RED)
      └─network.target @9.952s
        └─systemd-networkd.service @9.471s +480ms (RED)
          └─dbus.service @8.012s
            └─basic.target @7.944s
              └─sockets.target @7.944s
                └─pcscd.socket @7.944s
                  └─sysinit.target @7.944s
                    └─systemd-timesyncd.service @7.805s +138ms (RED)
                      └─systemd-tmpfiles-setup.service @7.675s +129ms (RED)
                        └─local-fs.target @7.674s
                          └─boot.mount @7.446s +228ms (RED)
                            └─dev-disk-by\x2duuid-552E\x2d4A68.device @7.434s

Last edited by quequotion (2017-06-23 00:47:28)

Offline

#7 2017-06-23 19:16:09

seth
Member
Registered: 2012-09-03
Posts: 7,208

Re: [SOLVED] org.cups.cupsd.service delays boot

mmm... does it take equally long to (stop and) start the service at runtime?
Network printers or smb shares?

Offline

#8 2017-06-23 20:20:55

quequotion
Member
From: Oita, Japan
Registered: 2013-07-29
Posts: 620
Website

Re: [SOLVED] org.cups.cupsd.service delays boot

seth wrote:

mmm... does it take equally long to (stop and) start the service at runtime?

EDIT: I did not realize systemd-analyze can be used on services started after boot:

systemd-analyze critical-chain org.cups.cupsd.service
The time after the unit is active or started is printed after the "@" character.
The time the unit takes to start is printed after the "+" character.

org.cups.cupsd.service +140ms
└─network.target @10.056s
  └─systemd-networkd.service @9.560s +495ms
    └─dbus.service @8.088s
      └─basic.target @8.010s
        └─sockets.target @8.010s
          └─pcscd.socket @8.010s
            └─sysinit.target @7.964s
              └─systemd-timesyncd.service @7.811s +152ms
                └─systemd-tmpfiles-setup.service @7.686s +122ms
                  └─local-fs.target @7.685s
                    └─boot.mount @7.526s +158ms
                      └─dev-disk-by\x2duuid-552E\x2d4A68.device @7.502s

Network printer

Yes, the printer (wifi) and the pc (ethernet) are connected to a local router and have fixed IPs.

smb shares?

No.

Last edited by quequotion (2017-06-23 20:27:21)

Offline

#9 2017-06-23 20:23:19

seth
Member
Registered: 2012-09-03
Posts: 7,208

Re: [SOLVED] org.cups.cupsd.service delays boot

I guess I don't have to tell what to try next, right? ;-)

Offline

#10 2017-06-23 20:30:26

quequotion
Member
From: Oita, Japan
Registered: 2013-07-29
Posts: 620
Website

Re: [SOLVED] org.cups.cupsd.service delays boot

seth wrote:

I guess I don't have to tell what to try next, right? ;-)

I've already tested with the printer on and off during boot (look back a few posts), which was inconclusive. I haven't tried uninstalling the printer because I still have nightmares about getting it to work in the first place. If you think that's what I need to do, I can give it a shot, but it might be weeks before I can reliably print again.

Offline

#11 2017-06-23 20:34:00

seth
Member
Registered: 2012-09-03
Posts: 7,208

Re: [SOLVED] org.cups.cupsd.service delays boot

And if you pull eth0 for a test?

Offline

#12 2017-06-23 20:58:50

quequotion
Member
From: Oita, Japan
Registered: 2013-07-29
Posts: 620
Website

Re: [SOLVED] org.cups.cupsd.service delays boot

seth wrote:

And if you pull eth0 for a test?

It's an onboard NIC, so I'll have to do that with something like modprobe.blacklist=tg3 as a kernel paramater (and not use the internet for a while).

I'll be back with results... probably...

Last edited by quequotion (2017-06-23 20:59:09)

Offline

#13 2017-06-23 21:00:48

seth
Member
Registered: 2012-09-03
Posts: 7,208

Re: [SOLVED] org.cups.cupsd.service delays boot

It should suffice to unplug the cable.

Offline

#14 2017-06-23 21:24:00

quequotion
Member
From: Oita, Japan
Registered: 2013-07-29
Posts: 620
Website

Re: [SOLVED] org.cups.cupsd.service delays boot

Unfortunately, not much difference.
Offline blame:

          5.390s dev-md126p2.device
          4.014s org.cups.cupsd.service
          2.978s ldconfig.service
          2.873s udisks2.service
          2.228s polkit.service
          2.205s systemd-hwdb-update.service
          1.990s upower.service
          1.476s lm_sensors.service
          1.386s systemd-udevd.service
          1.283s systemd-journald.service
          1.277s systemd-logind.service
          1.268s bluetooth.service
          1.103s lightdm.service
          1.040s accounts-daemon.service
           907ms systemd-modules-load.service
           689ms systemd-tmpfiles-setup-dev.service
           642ms systemd-sysusers.service
           560ms resume.swap
           403ms systemd-networkd.service
           325ms systemd-sysctl.service
           301ms systemd-journal-catalog-update.service
           289ms sys-kernel-debug.mount
           289ms dev-mqueue.mount
           274ms systemd-tmpfiles-setup.service
           268ms systemd-random-seed.service
           253ms colord.service
           238ms alsa-restore.service
           225ms systemd-localed.service
           213ms dev-hugepages.mount
           212ms systemd-remount-fs.service
           194ms systemd-timesyncd.service
           193ms systemd-udev-trigger.service
           123ms systemd-binfmt.service
           121ms boot.mount
           102ms user@1000.service
            91ms kmod-static-nodes.service
            73ms systemd-journal-flush.service
            69ms systemd-hostnamed.service
            57ms systemd-update-utmp.service
            35ms rtkit-daemon.service
            33ms systemd-update-done.service
            11ms sys-fs-fuse-connections.mount
             6ms systemd-user-sessions.service
             5ms proc-sys-fs-binfmt_misc.mount
             1ms sys-kernel-config.mount
             1ms tmp.mount

Offline chain:

The time after the unit is active or started is printed after the "@" character.
The time the unit takes to start is printed after the "+" character.

graphical.target @17.014s
└─multi-user.target @17.013s
  └─cups-browsed.service @17.013s
    └─org.cups.cupsd.service @12.998s +4.014s
      └─network.target @12.995s
        └─systemd-networkd.service @12.591s +403ms
          └─dbus.service @11.348s
            └─basic.target @11.321s
              └─sockets.target @11.321s
                └─pcscd.socket @11.321s
                  └─sysinit.target @11.301s
                    └─systemd-update-done.service @11.267s +33ms
                      └─ldconfig.service @8.288s +2.978s
                        └─local-fs.target @8.288s
                          └─boot.mount @8.166s +121ms
                            └─dev-disk-by\x2duuid-552E\x2d4A68.device @8.126s

Offline

#15 2017-06-23 21:53:57

loqs
Member
Registered: 2014-03-06
Posts: 4,869

Re: [SOLVED] org.cups.cupsd.service delays boot

Can you not switch from target based activation to socket based activation for cups?

Offline

#16 2017-06-24 10:07:03

quequotion
Member
From: Oita, Japan
Registered: 2013-07-29
Posts: 620
Website

Re: [SOLVED] org.cups.cupsd.service delays boot

loqs wrote:

Can you not switch from target based activation to socket based activation for cups?

As far as I know this is the default systemd configuration for cups. The nightmares I mentioned before derive from getting my particular printer drivers installed and working (it's an Epson EP-806A multifunction unit; getting both the scanner and the printer working correctly over wifi at the same time was hell, but did not involve doing anything to systemd services).

There is already a socket active:

$ systemctl status org.cups.cupsd.socket
● org.cups.cupsd.socket - CUPS Scheduler
   Loaded: loaded (/usr/lib/systemd/system/org.cups.cupsd.socket; enabled; vendor preset: disabled)
   Active: active (running) since Sat 2017-06-24 18:50:27 JST; 7min ago
   Listen: /run/cups/cups.sock (Stream)

Which must be responsible for launching the service, as it is--and as far as I know always has been--"disabled":

$ systemctl status org.cups.cupsd.service
● org.cups.cupsd.service - CUPS Scheduler
   Loaded: loaded (/usr/lib/systemd/system/org.cups.cupsd.service; disabled; vendor preset: disabled)
   Active: active (running) since Sat 2017-06-24 18:50:34 JST; 10min ago
     Docs: man:cupsd(8)
 Main PID: 540 (cupsd)
   Status: "Scheduler is running..."
    Tasks: 2 (limit: 4915)
   CGroup: /system.slice/org.cups.cupsd.service
           └─540 /usr/bin/cupsd -l

Last edited by quequotion (2017-06-24 10:08:58)

Offline

#17 2017-06-24 11:34:28

loqs
Member
Registered: 2014-03-06
Posts: 4,869

Re: [SOLVED] org.cups.cupsd.service delays boot

cups-browsed.service has this install section

[Install]
WantedBy=multi-user.target

You can see this in the critical chain cups-browsed.service under multi-user.target,  from /usr/lib/systemd/system/cups-browsed.service

Requires=org.cups.cupsd.service

This starts org.cups.cupsd.service.  So booting the system to graphical.target or multi-user.target will start org.cups.cupsd.service not socket based activation.
You have followed CUPS#cups-browsed and I agree the wiki page does not mention socket based activation.
However if all the printer queues are fully configured you may be able to disable cups-browsed.service and use org.cups.cupsd.socket to starts cups when something attempts to connect to the service via the socket.
Edit:
To test you would also need to disable org.cups.cupsd.service then ensure org.cups.cupsd.socket is still enabled.

Last edited by loqs (2017-06-24 11:46:37)

Offline

#18 2017-06-25 00:13:02

quequotion
Member
From: Oita, Japan
Registered: 2013-07-29
Posts: 620
Website

Re: [SOLVED] org.cups.cupsd.service delays boot

loqs wrote:

You have followed CUPS#cups-browsed and I agree the wiki page does not mention socket based activation.
However if all the printer queues are fully configured you may be able to disable cups-browsed.service and use org.cups.cupsd.socket to starts cups when something attempts to connect to the service via the socket.

That's the ticket! Thank you loqs (and everyone else who helped)!

Cups is down to a much more reasonable time:

$ systemd-analyze blame | grep cups
          1.352s org.cups.cupsd.service

EDIT: Added a note in the wiki, linked to loqs's post.

Last edited by quequotion (2017-06-25 00:30:06)

Offline

Board footer

Powered by FluxBB