Trying to understand the delay

Heyas

As you know me, i have scripts for about almost every aspect of my IT life.
This time, i'm having issues to figure out why my script to connect to my wifi spots takes so long when started as service.

The service file (the after:local-fs.target is for 'home installations'):

cat /etc/systemd/system/wifi-home.service 
[Unit]
Description=Wifi-home
After=local-fs.target

[Service]
Type=oneshot
RemainAfterExit=yes
ExecStart=/home/sea/prjs/connect/connect wifi home
ExecStop=/home/sea/prjs/connect/connect wifi restart

[Install]
WantedBy=multi-user.target

Now, when i connect to my wifi spots using the script, it is 'quite fast'..

0 sea # time connect wifi home
# | Connect (0.4)                                                           sea @ 2015-09-07 00:36:21 | #
# |                                     Wifi (0.4) (wlp3s0) Start                                     | #
# | Connect (0.4) wifi home                                                                  [     ] | #

real	0m6.444s
user	0m0.590s
sys	0m0.113s

But during boot, it takes like the tripple time... :frowning:

alias blame ; blame
alias blame='systemd-analyze critical-chain;systemd-analyze blame;systemd-analyze'

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 @19.308s
multi-user.target @19.306s
  systemd-logind.service @18.423s +882ms
    basic.target @16.236s
      sockets.target @16.236s
        dbus.socket @16.236s
          sysinit.target @16.216s
            systemd-update-utmp.service @16.014s +201ms
              systemd-tmpfiles-setup.service @15.918s +95ms
                local-fs.target @15.918s
                  home.mount @15.669s +247ms
                    dev-mapper-home.device @15.668s
         16.485s wifi-home.service
          8.050s dev-sda12.device
          6.247s systemd-cryptsetup@home.service
          4.673s systemd-journal-flush.service
          1.683s udisks2.service
          1.321s systemd-vconsole-setup.service
          1.273s polkit.service
          1.085s systemd-fsck-root.service
           959ms avahi-daemon.service
           938ms user@1000.service
           920ms systemd-udevd.service
           882ms systemd-logind.service
           746ms boot-efi.mount
           727ms systemd-ask-password-wall.service
           712ms systemd-journald.service
           661ms systemd-tmpfiles-setup-dev.service
           579ms tmp.mount
           495ms systemd-backlight@backlight:intel_backlight.service
           482ms sys-kernel-debug.mount
           470ms dev-hugepages.mount
           470ms dev-mqueue.mount
           460ms systemd-sysctl.service
           342ms systemd-modules-load.service
           331ms systemd-rfkill@rfkill2.service
           262ms systemd-user-sessions.service
           255ms mnt-shared.mount
           247ms home.mount
           201ms systemd-update-utmp.service
           174ms kmod-static-nodes.service
           157ms systemd-fsck@dev-sda11.service
           133ms boot.mount
           110ms systemd-random-seed.service
            95ms systemd-tmpfiles-setup.service
            87ms sys-kernel-config.mount
            70ms systemd-rfkill@rfkill1.service
            69ms systemd-remount-fs.service
            65ms systemd-udev-trigger.service
             2ms alsa-restore.service
             2ms sys-fs-fuse-connections.mount
Startup finished in 2.370s (firmware) + 2.920s (loader) + 3.160s (kernel) + 34.909s (userspace) = 43.361s

From here on i have not much of an idea where to dig.
The systemd-analyze plot > boot.png only showed that the service is loaded properly after local-fs.target was reached, and that it took until graphical.target was loaded.

So my question is, any idea why there is such a time difference, or how i could figure out more myself?
Thank you in advance.

---------- Post updated at 13:46 ---------- Previous update was at 00:51 ----------

time su -c "systemctl start wifi-home"
Passwort: 

real	0m9.077s
user	0m0.033s
sys	0m0.010s
systemctl status wifi-home
 wifi-home.service - Wifi-home
   Loaded: loaded (/etc/systemd/system/wifi-home.service; enabled; vendor preset: disabled)
   Active: active (exited) since Mon 2015-09-07 13:33:36 CEST; 33s ago
  Process: 12702 ExecStop=/home/sea/prjs/connect/connect wifi restart
  Process: 16625 ExecStart=/home/sea/prjs/connect/connect wifi home (code=exited, status=0/SUCCESS)
 Main PID: 16625 (code=exited, status=0/SUCCESS)
   CGroup: /system.slice/wifi-home.service
           16689 bash /usr/share/connect/to/wifi home
           16692 dhcpcd -B
           16737 wpa_supplicant -B -iwlp3s0 -c/root/.config/connect/wifi/home -f/connect/wifi.log

I even removed the After=local-fs.target as i had moved the creds to root account, and restarted (stop,disable,enable,start) the service in the hope to speed up the process, as i would not need to wait for /home decryption.

So, i'm actualy getting 3 different times, ~6 secs when calling the programm directly, ~9 secs when calling the service directly, but ~16-18secs when booting.

Any ideas please why i might getting such different times for the same command?
Where to dig now?
What info do you need to tell me where to look?

tia

Which OS ?

You might want to ask on the systemd mailing list. They are very responsive usually.

I don't want to guess. Systemd behavior is not necessarily my friend.

Sorry for the delay, but since its not breaking usability i forgot about it, as i had more urgent matters.
@ brij123: Arch
@ cjox, good idea, did so now: https://github.com/systemd/systemd/issues
Thanks for your replies.