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

Sedat Dilek
2020-05-31T07:12:54Z

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 -