Re: [PATCHSET v5 0/12] Add support for async buffered reads

[Sedat Dilek <sedat.dilek@gmail.com>]

On Sun, May 31, 2020 at 9:04 AM Sedat Dilek <sedat.dilek@gmail.com> wrote:
>
> On Sun, May 31, 2020 at 3:57 AM Jens Axboe <axboe@kernel.dk> wrote:
> >
> > On 5/30/20 12:57 PM, Sedat Dilek wrote:
> > > Here are the numbers with your patchset:
> > >
> > > # cat systemd-analyze-time_5.7.0-rc7-4-amd64-clang_2nd-try.txt
> > > Startup finished in 7.229s (kernel) + 1min 18.304s (userspace) = 1min 25.534s
> > > graphical.target reached after 1min 18.286s in userspace
> >
> > Can you see if this makes a difference?
> >
> > diff --git a/include/linux/blk_types.h b/include/linux/blk_types.h
> > index c296463c15eb..ccb895f911b1 100644
> > --- a/include/linux/blk_types.h
> > +++ b/include/linux/blk_types.h
> > @@ -374,8 +374,7 @@ enum req_flag_bits {
> >  #define REQ_INTEGRITY          (1ULL << __REQ_INTEGRITY)
> >  #define REQ_FUA                        (1ULL << __REQ_FUA)
> >  #define REQ_PREFLUSH           (1ULL << __REQ_PREFLUSH)
> > -#define REQ_RAHEAD             \
> > -       ((1ULL << __REQ_RAHEAD) | (1ULL << __REQ_NOWAIT))
> > +#define REQ_RAHEAD             (1ULL << __REQ_RAHEAD)
> >  #define REQ_BACKGROUND         (1ULL << __REQ_BACKGROUND)
> >  #define REQ_NOWAIT             (1ULL << __REQ_NOWAIT)
> >  #define REQ_CGROUP_PUNT                (1ULL << __REQ_CGROUP_PUNT)
> >
>
> Looks good!
>
> With your patch I now get...
>
> # cat systemd-analyze-time_5.7.0-rc7-6-amd64-clang.txt
> Startup finished in 6.199s (kernel) + 45.143s (userspace) = 51.343s
> graphical.target reached after 45.123s in userspace
>
> # cat systemd-analyze-blame_5.7.0-rc7-6-amd64-clang.txt
> 25.029s udisks2.service
> 24.582s accounts-daemon.service
> 19.257s dev-sdc2.device
> 18.016s polkit.service
> 17.857s avahi-daemon.service
> 17.730s NetworkManager.service
> 17.433s rtkit-daemon.service
> 16.558s switcheroo-control.service
> 16.547s wpa_supplicant.service
> 16.538s systemd-logind.service
> 16.078s smartmontools.service
> 14.982s fwupd-refresh.service
> 14.580s NetworkManager-wait-online.service
> 13.630s zramswap.service
> 11.286s fwupd.service
>  8.153s rsyslog.service
>  6.858s gpm.service
>  6.835s e2scrub_reap.service
>  6.449s ModemManager.service
>  6.439s networking.service
>  5.881s packagekit.service
>  3.696s systemd-udevd.service
>  3.322s apparmor.service
>  3.277s exim4.service
>  2.910s alsa-restore.service
>  1.611s systemd-tmpfiles-setup.service
>  1.540s bluetooth.service
>  1.448s systemd-journal-flush.service
>  1.353s keyboard-setup.service
>  1.322s atd.service
>  1.239s systemd-modules-load.service
>  1.216s binfmt-support.service
>  1.060s modprobe@drm.service
>   994ms systemd-journald.service
>   983ms upower.service
>   937ms systemd-sysusers.service
>   914ms ifupdown-wait-online.service
>   904ms pppd-dns.service
>   710ms systemd-udev-trigger.service
>   666ms dev-hugepages.mount
>   650ms dev-mqueue.mount
>   649ms sys-kernel-debug.mount
>   647ms sys-kernel-tracing.mount
>   607ms console-setup.service
>   590ms systemd-tmpfiles-setup-dev.service
>   570ms systemd-timesyncd.service
>   508ms systemd-random-seed.service
>   461ms systemd-backlight@backlight:intel_backlight.service
>   433ms user@1000.service
>   422ms systemd-remount-fs.service
>   365ms systemd-sysctl.service
>   279ms kmod-static-nodes.service
>   246ms proc-sys-fs-binfmt_misc.mount
>   202ms systemd-rfkill.service
>   130ms systemd-user-sessions.service
>   104ms systemd-update-utmp.service
>    25ms user-runtime-dir@1000.service
>    14ms systemd-update-utmp-runlevel.service
>     6ms sys-fs-fuse-connections.mount
>     4ms ifupdown-pre.service
>
> # cat systemd-analyze-critical-chain_5.7.0-rc7-6-amd64-clang.txt
> The time when unit became active or started is printed after the "@" character.
> The time the unit took to start is printed after the "+" character.
>
> graphical.target @45.123s
> └─multi-user.target @45.122s
>   └─exim4.service @41.842s +3.277s
>     └─network-online.target @41.840s
>       └─NetworkManager-wait-online.service @27.259s +14.580s
>         └─NetworkManager.service @9.522s +17.730s
>           └─dbus.service @9.514s
>             └─basic.target @9.328s
>               └─sockets.target @9.327s
>                 └─dbus.socket @9.327s
>                   └─sysinit.target @9.202s
>
> └─systemd-backlight@backlight:intel_backlight.service @21.927s +461ms
>                       └─system-systemd\x2dbacklight.slice @21.925s
>                         └─system.slice @2.529s
>                           └─-.slice @2.529s
>
> Will you send a separate patch on this?
>
> Feel free to add:
> Reported-by: Sedat Dilek <sedat.dilek@gmail.com>
> Tested-by: Sedat Dilek <sedat.dilek@gmail.com>
>
> My kernel-config and dmesg-output are attached.
>
> Thanks Jens!
>

2nd-try (reboot into system with activated WLAN before startup)...

# systemd-analyze --no-pager time
Startup finished in 6.044s (kernel) + 41.370s (userspace) = 47.414s
graphical.target reached after 40.431s in userspace

# systemd-analyze --no-pager blame | head -20
24.674s udisks2.service
24.348s accounts-daemon.service
19.504s dev-sdc2.device
18.677s polkit.service
18.283s avahi-daemon.service
18.231s NetworkManager.service
17.918s rtkit-daemon.service
16.948s switcheroo-control.service
16.932s wpa_supplicant.service
16.928s systemd-logind.service
15.335s smartmontools.service
14.063s zramswap.service
11.507s NetworkManager-wait-online.service
11.279s rsyslog.service
 7.490s gpm.service
 6.556s packagekit.service
 6.506s networking.service
 6.446s e2scrub_reap.service
 5.404s ModemManager.service
 3.329s systemd-udevd.service

# systemd-analyze critical-chain
The time when unit became active or started is printed after the "@" character.
The time the unit took to start is printed after the "+" character.

graphical.target @40.431s
└─multi-user.target @40.431s
  └─exim4.service @38.726s +1.701s
    └─network-online.target @38.723s
      └─NetworkManager-wait-online.service @27.215s +11.507s
        └─NetworkManager.service @8.978s +18.231s
          └─dbus.service @8.971s
            └─basic.target @8.862s
              └─sockets.target @8.861s
                └─dbus.socket @8.861s
                  └─sysinit.target @8.723s

└─systemd-backlight@backlight:intel_backlight.service @20.555s +812ms
                      └─system-systemd\x2dbacklight.slice @19.665s
                        └─system.slice @2.473s
                          └─-.slice @2.473s

Nice!

- Sedat -