Bug 2236438 - Anaconda is very slow to show a window after clicking install in gnome-initial-setup
Summary: Anaconda is very slow to show a window after clicking install in gnome-initia...
Keywords:
Status: MODIFIED
Alias: None
Product: Fedora
Classification: Fedora
Component: anaconda
Version: rawhide
Hardware: x86_64
OS: Linux
unspecified
medium
Target Milestone: ---
Assignee: Jiri Konecny
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
: 2232635 (view as bug list)
Depends On:
Blocks: AnacondaWebUITracker
TreeView+ depends on / blocked
 
Reported: 2023-08-31 09:43 UTC by Allan Day
Modified: 2024-03-01 21:28 UTC (History)
13 users (show)

Fixed In Version: anaconda-40.18-1
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed:
Type: ---
Embargoed:


Attachments (Terms of Use)

Description Allan Day 2023-08-31 09:43:34 UTC
Testing an F39 nightly image from yesterday [1] as a VM, I observe the following in the initial live session:

 1. Initial setup launches, and I can go through the first two setup steps
 2. At the "try or install" step, I click "install"
 3. The initial setup window closes, and then it takes 24 seconds for the installer window to appear. During that time, I'm left looking at a blank desktop with no feedback that anything is happening in the background.

As a user, you're left wondering if something is broken. It's a very poor experience for the default install path.

[1] https://kojipkgs.fedoraproject.org/compose/branched/Fedora-39-20230830.n.0/compose/Workstation/x86_64/iso/Fedora-Workstation-Live-x86_64-39-20230830.n.0.iso

Reproducible: Always

Comment 1 Allan Day 2023-08-31 09:47:28 UTC
I'm proposing this as a final F39 blocker. A blank screen with no feedback for this length of time isn't an acceptable user experience.

Comment 2 Allan Day 2023-08-31 10:11:45 UTC
Created attachment 1986299 [details]
Screen recording

Here's a screen recording of the issue. In this test the time from clicking install to the installer window appearing is ~18 seconds, so better than in my previous test, but still a long way from being acceptable.

Comment 3 Christian Hergert 2023-08-31 17:22:25 UTC
I had to start things from a live session so that I could get some basic sysprof stuff setup.

So at second 10 of my capture (which involved changing some VTs, so there is a little extra going on) it looks like:

@ 9.245 s: gio-launch-desktop
@ 9.246 s: liveinst at 9.246
@ 9.300 s: systemd-userwork starts
a series of modprobe/sed
@ 9.375 s: rpm starts
some greap/cat/getenforce
@ 9.392 s: anaconda-cleanup runs for a bit
@ 9.561 s: ldconfig runs?
@ 9.674 s: a bunch of sh/udevadm/udev-worker
some spawn/cdrom_id/ata_id/pktsetup
@ 9.800 s: e2fsck runs
a bunch of dmsetup for about 200 msec
@10.053 s: anaconda finally starts
@10.300 s: more ldconfig
A second passes ...
@11.403 s: losetup
a dbus-daemon is started (not dbus-broker)
python3, start-module, sleep
more ldconfig, losetup, udevadm, systemctl, modprobe, cdrom_id, ata_id, lsblk
@14.628 s: mount
@14.742 s: webui-desktop FINALLY starts 5.5 seconds later
@14.758 s: cockpit-ws
@14.763 s: cockpit-bridge
@14.785 s: firefox STARTS
@14.846 s: run-mozilla.sh
@14.932 s: glxtest
@14.958 s: ssh-agent
@15.440 s: firefox sandbox forked, main thread starts shortly after, then socket process
a bunch more web processes start
@18.500 s: firefox seems to be available
@21.500 s: more firefox workers


And this is on a systme where i've already run that once (via the initial displayed gdm) with 8gb of ram in a VM, so everything *should* be cached from the ISO at that point.

Comment 4 Ray Strode [halfline] 2023-08-31 17:51:36 UTC
(sorry midair collision with hergertme)

So i added some printfs and ran this script over anaconda.log:

```
/bin/bash

# Check if a file is provided
if [ "$#" -ne 1 ]; then
    echo "Usage: $0 <logfile>"
    exit 1
fi

# Initialize variables
declare -i prevTime=0
declare -i currentTime=0
declare -i timeDifference=0
declare -i index=0
prevLine=""

# Declare arrays to hold the lines and their time differences
linePairs=()
timeDifferences=()

# Read the log file line by line
while read -r line; do
    if [[ $line =~ ^([0-9]{2}):([0-9]{2}):([0-9]{2}),([0-9]{3}) ]]; then
        hours=${BASH_REMATCH[1]}
        minutes=${BASH_REMATCH[2]}
        seconds=${BASH_REMATCH[3]}
        milliseconds=${BASH_REMATCH[4]}
        currentTime=$((10#$hours * 3600000 + 10#$minutes * 60000 + 10#$seconds * 1000 + 10#$milliseconds))

        if [ "$prevTime" -ne 0 ]; then
            timeDifference=$((currentTime - prevTime))
            linePair="$prevLine → $line"
            linePairs[index]="$linePair"
            timeDifferences[index]=$timeDifference
            index=$((index + 1))
        fi

        prevTime=$currentTime
        prevLine="$line"
    fi
done < "$1"

# Sort the lines based on timeDifferences
for i in $(seq 0 $((index - 1))); do
    for j in $(seq 0 $((index - i - 2))); do
        if [ "${timeDifferences[j]}" -gt "${timeDifferences[j+1]}" ]; then
            # Swap timeDifferences
            temp=${timeDifferences[j]}
            timeDifferences[j]=${timeDifferences[j+1]}
            timeDifferences[j+1]=$temp

            # Swap linePairs
            temp="${linePairs[j]}"
            linePairs[j]="${linePairs[j+1]}"
            linePairs[j+1]="$temp"
        fi
    done
done

# Print the sorted linePairs along with their timeDifferences
for i in $(seq 0 $((index - 1))); do
    echo "${timeDifferences[i]}ms: ${linePairs[i]}"
done
```

and got this output:

liveuser@localhost-live:/srv/sources/github/anaconda$ sh sortlog.sh /tmp/anaconda.log |sort -rn | head -15
2225ms: 13:21:18,423 INF core.dbus: Got connection → 13:21:20,648 INF main: Done starting dbus
474ms: 13:21:21,527 INF core.threads: Thread Done: AnaPayloadThread (140548321003200) → 13:21:22,001 INF core.threads: Thread Done: AnaTimeInitThread (140548337788608)
204ms: 13:21:21,028 INF main: waiting for geolocation → 13:21:21,232 INF startup_utils: Geoloc: using timezone determined by geolocation
175ms: 13:21:21,242 DBG core.threads: Waiting for thread AnaStorageThread to exit → 13:21:21,417 INF core.threads: Thread Done: AnaStorageThread (140548367185600)
142ms: 13:21:20,726 INF main: Done activating keyboard layout → 13:21:20,868 INF main: Initializing security
109ms: 13:21:21,418 DBG core.threads: Waiting for thread AnaTimeInitThread to exit → 13:21:21,527 INF core.threads: Thread Done: AnaPayloadThread (140548321003200)
91ms: 13:21:20,904 INF main: device stuff → 13:21:20,995 DBG core.storage: LABEL=OEMDRV matches [] for devicetree=None and disks_only=True
71ms: 13:21:18,327 WRN misc: /usr/lib64/python3.12/site-packages/pyanaconda/core/users.py:31: DeprecationWarning: 'crypt' is deprecated and slated for removal in Python 3.13 → 13:21:18,398 INF startup_utils: check_memory(): total:2081, needed:320
57ms: 13:21:20,665 INF startup_utils: Parsing kickstart: /usr/share/anaconda/interactive-defaults.ks → 13:21:20,722 INF main: Done parsing kickstart file
26ms: 13:21:18,301 INF core.util: Reporting the IPMI event: 7 → 13:21:18,327 WRN misc: /usr/lib64/python3.12/site-packages/pyanaconda/core/users.py:31: DeprecationWarning: 'crypt' is deprecated and slated for removal in Python 3.13
15ms: 13:21:20,648 INF main: Running pre scripts → 13:21:20,663 INF main: Done running pre scripts
15ms: 13:21:18,407 INF misc: Writing the runtime configuration to: /run/anaconda/anaconda.conf → 13:21:18,422 INF core.dbus: Connecting to the Anaconda bus at unix:path=/tmp/dbus-rbJ0YEEXtH,guid=d915d3dad6ef6a7cacf5536064f0cc0e.
9ms: 13:21:22,002 DBG ui.webui: web-ui: starting cockpit web view → 13:21:22,011 DBG ui.webui: cockpit web view has been started
9ms: 13:21:21,004 INF main: done system clock → 13:21:21,013 INF main: starting payload tasks
8ms: 13:21:20,881 DBG anaconda: setting display mode to GUI → 13:21:20,889 INF network: got 0 NTP servers from DHCP

So the slowest thing is starting the special anaconda message bus. The next amount of time is waiting for AnaTimeInitThread to finish and (you can't see this from above, but looking at the whole log), waiting for AnaPayloadThread to finish, and waiting for AnaStorageThread to finish.

I think geolocation and timeinit are supposed to be skipped in live image ? If so that should cut out a significant amount of time. I bet there's low hanging fruit with the message bus too. i'll dig deeper.

Comment 5 Ray Strode [halfline] 2023-08-31 17:56:05 UTC
Christian, can you try commenting out the 

rm -rf ${FIREFOX_PROFILE_PATH} in /usr/libexec/webui-desktop

and see if that improves firefox start up time ? If so, we should probably look into generating the firefox profile at build time instead of startup

Comment 6 Ray Strode [halfline] 2023-08-31 17:56:41 UTC
(of course you'll have to run the installer once to make sure the profile gets generated before profiling)

Comment 7 Ray Strode [halfline] 2023-08-31 18:57:20 UTC
(In reply to Ray Strode [halfline] from comment #4)
> So the slowest thing is starting the special anaconda message bus.
...
> I bet there's low hanging fruit with the message bus too. i'll dig deeper.

So it's not just starting the message bus, it's starting anaconda services over the bus. that's what's taking all the time:

```
14:48:52,996 INFO boss: init
14:48:53,003 INFO boss: start modules
14:48:53,003 INFO boss: StartServiceByName $org.fedoraproject.Anaconda.Modules.Services
14:48:53,005 INFO boss: StartServiceByName $org.fedoraproject.Anaconda.Modules.Security
14:48:53,005 INFO boss: StartServiceByName $org.fedoraproject.Anaconda.Modules.Users
14:48:53,005 INFO boss: StartServiceByName $org.fedoraproject.Anaconda.Modules.Runtime
14:48:53,006 INFO boss: StartServiceByName $org.fedoraproject.Anaconda.Modules.Payloads
14:48:53,006 INFO boss: StartServiceByName $org.fedoraproject.Anaconda.Modules.Storage
14:48:53,006 INFO boss: StartServiceByName $org.fedoraproject.Anaconda.Modules.Localization
14:48:53,006 INFO boss: StartServiceByName $org.fedoraproject.Anaconda.Modules.Timezone
14:48:53,006 INFO boss: StartServiceByName $org.fedoraproject.Anaconda.Modules.Network
14:48:53,007 INFO boss: StartServiceByName $org.fedoraproject.Anaconda.Addons.Kdump
14:48:53,007 INFO boss: StartServiceByName $org.fedoraproject.Anaconda.Modules.Subscription
14:48:53,007 INFO boss: done start modules
14:48:53,007 INFO boss: process callbacks
14:48:53,726 INFO boss: done StartServiceByName $org.fedoraproject.Anaconda.Addons.Kdump
14:48:54,158 INFO boss: done StartServiceByName $org.fedoraproject.Anaconda.Modules.Runtime
14:48:54,158 INFO boss: Service $org.fedoraproject.Anaconda.Modules.Runtime started successfully
14:48:54,182 INFO boss: done StartServiceByName $org.fedoraproject.Anaconda.Modules.Security
14:48:54,183 INFO boss: Service $org.fedoraproject.Anaconda.Modules.Security started successfully
14:48:54,202 INFO boss: done StartServiceByName $org.fedoraproject.Anaconda.Modules.Subscription
14:48:54,206 INFO boss: done StartServiceByName $org.fedoraproject.Anaconda.Modules.Users
14:48:54,206 INFO boss: Service $org.fedoraproject.Anaconda.Modules.Users started successfully
14:48:54,220 INFO boss: done StartServiceByName $org.fedoraproject.Anaconda.Modules.Services
14:48:54,221 INFO boss: Service $org.fedoraproject.Anaconda.Modules.Services started successfully
14:48:54,243 INFO boss: done StartServiceByName $org.fedoraproject.Anaconda.Modules.Network
14:48:54,243 INFO boss: Service $org.fedoraproject.Anaconda.Modules.Network started successfully
14:48:54,262 INFO boss: done StartServiceByName $org.fedoraproject.Anaconda.Modules.Payloads
14:48:54,263 INFO boss: Service $org.fedoraproject.Anaconda.Modules.Payloads started successfully
14:48:54,562 INFO boss: done StartServiceByName $org.fedoraproject.Anaconda.Modules.Storage
14:48:54,562 INFO boss: Service $org.fedoraproject.Anaconda.Modules.Storage started successfully
14:48:54,858 INFO boss: done StartServiceByName $org.fedoraproject.Anaconda.Modules.Timezone
14:48:54,858 INFO boss: Service $org.fedoraproject.Anaconda.Modules.Timezone started successfully
14:48:54,868 INFO boss: done StartServiceByName $org.fedoraproject.Anaconda.Modules.Localization
14:48:54,868 INFO boss: Service $org.fedoraproject.Anaconda.Modules.Localization started successfully
14:48:54,869 INFO boss: done process callbacks
```

You see Localization, Timezone, and Storage are taking the longest. I wonder if we could start the webui before the services are started.
maybe even rely on bus activation so they get started as needed instead of up front?

Comment 8 Ray Strode [halfline] 2023-08-31 19:13:58 UTC
so just doing this:

╎❯ git diff -U2 pyanaconda/modules/boss/module_manager/start_modules.py
diff --git a/pyanaconda/modules/boss/module_manager/start_modules.py b/pyanaconda/modules/boss/module_manager/start_modules.py
index 4532a621a6..fc8cb016bb 100644
--- a/pyanaconda/modules/boss/module_manager/start_modules.py
+++ b/pyanaconda/modules/boss/module_manager/start_modules.py
@@ -75,5 +75,5 @@ class StartModulesTask(Task):
 
         # Process the callbacks of the asynchronous calls.
-        self._process_callbacks(self._module_observers)
+        #self._process_callbacks(self._module_observers)
 
         return self._module_observers

Takes 3 seconds off startup. _process_callbacks is where it sits and waits for all its dbus services to finish starting. I think it's doing this so that it can fail up front if one of them fails to start, but I don't think adding 3 seconds to start up is good tradeoff for a very slightly more up front catastrophic failure in a seldom seen error case.

Comment 9 Ray Strode [halfline] 2023-08-31 20:33:00 UTC
okay i've decided to take a different tact, and use cProfile (This is after commenting the _process_callbacks):

diff --git a/anaconda.py b/anaconda.py
index b2df895be6..7d3ba650c3 100755
--- a/anaconda.py
+++ b/anaconda.py
@@ -29,7 +29,9 @@ import sys
 import time
 import signal
 import pid
-
+import cProfile
+import pstats
+from pstats import SortKey
 
 def exitHandler(rebootData):
     # Clear the list of watched PIDs.
@@ -172,6 +174,8 @@ if __name__ == "__main__":
         sys.exit(1)
 
     print("Starting installer, one moment...")
+    profiler = cProfile.Profile()
+    profiler.enable()
 
     # Allow a file to be loaded as early as possible
     try:
@@ -573,6 +577,10 @@ if __name__ == "__main__":
     startup_utils.wait_for_geolocation_and_use(geoloc_task_proxy, anaconda.display_mode)
 
     anaconda.intf.setup(ksdata)
+    profiler.disable()
+
+    stats = pstats.Stats(profiler).sort_stats(SortKey.CUMULATIVE)
+    stats.print_stats()
     anaconda.intf.run()


       2851370 function calls (2837908 primitive calls) in 6.487 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
   714/24    0.012    0.000    2.561    0.107 <frozen importlib._bootstrap>:1255(_find_and_load)
   690/20    0.004    0.000    2.561    0.128 <frozen importlib._bootstrap>:1210(_find_and_load_unlocked)
  1592/34    0.002    0.000    2.558    0.075 <frozen importlib._bootstrap>:392(_call_with_frames_removed)
   663/23    0.003    0.000    2.557    0.111 <frozen importlib._bootstrap>:817(_load_unlocked)
   616/22    0.002    0.000    2.556    0.116 <frozen importlib._bootstrap_external>:988(exec_module)
   619/22    0.004    0.000    2.548    0.116 {built-in method builtins.exec}
    88/84    0.001    0.000    2.399    0.029 /usr/lib/python3.12/site-packages/dasbus/client/handler.py:414(_call_method)
    88/85    0.000    0.000    2.383    0.028 /usr/lib/python3.12/site-packages/dasbus/client/handler.py:470(_get_method_reply)
    88/85    2.370    0.027    2.369    0.028 /usr/lib/python3.12/site-packages/dasbus/client/handler.py:49(sync_call)
   232/13    0.001    0.000    2.344    0.180 {built-in method builtins.__import__}
   561/72    0.006    0.000    2.341    0.033 <frozen importlib._bootstrap>:1296(_handle_fromlist)
        1    0.000    0.000    1.605    1.605 /usr/lib64/python3.12/site-packages/pyanaconda/startup_utils.py:1(<module>)
    55/54    0.000    0.000    1.512    0.028 /usr/lib/python3.12/site-packages/dasbus/client/proxy.py:154(__getattr__)
    57/56    0.000    0.000    1.477    0.026 /usr/lib/python3.12/site-packages/dasbus/client/proxy.py:204(_get_interface)
    75/73    0.000    0.000    1.477    0.020 /usr/lib/python3.12/site-packages/dasbus/client/handler.py:208(specification)
    31/30    0.000    0.000    1.476    0.049 /usr/lib/python3.12/site-packages/dasbus/client/handler.py:330(_get_specification)
        1    0.000    0.000    1.435    1.435 /usr/lib64/python3.12/site-packages/pyanaconda/localization.py:1(<module>)
        1    0.000    0.000    1.432    1.432 /usr/lib/python3.12/site-packages/langtable/__init__.py:1(<module>)
        1    0.000    0.000    1.425    1.425 /usr/lib/python3.12/site-packages/langtable/langtable.py:1(<module>)
        1    0.000    0.000    1.418    1.418 /usr/lib/python3.12/site-packages/langtable/langtable.py:2626(__init__)
        1    0.000    0.000    1.418    1.418 /usr/lib/python3.12/site-packages/langtable/langtable.py:2609(_init)
        5    0.000    0.000    1.417    0.283 /usr/lib/python3.12/site-packages/langtable/langtable.py:919(_read_file)
        5    0.000    0.000    1.415    0.283 /usr/lib/python3.12/site-packages/langtable/langtable.py:907(_expat_parse)
        5    0.742    0.148    1.415    0.283 {method 'ParseFile' of 'pyexpat.xmlparser' objects}
        4    0.000    0.000    1.220    0.305 /usr/lib64/python3.12/site-packages/pyanaconda/modules/common/task/__init__.py:28(sync_run_task)
        4    0.000    0.000    1.184    0.296 /usr/lib64/python3.12/site-packages/pyanaconda/anaconda.py:74(payload)
       12    1.181    0.098    1.181    0.098 {built-in method time.sleep}
        1    0.000    0.000    1.137    1.137 /usr/lib64/python3.12/site-packages/pyanaconda/anaconda.py:99(_get_dbus_payload_type)
      4/2    0.000    0.000    1.086    0.543 /usr/lib64/python3.12/threading.py:995(_bootstrap)
      4/2    0.006    0.001    1.086    0.543 /usr/lib64/python3.12/threading.py:1035(_bootstrap_inner)
      4/2    0.000    0.000    1.081    0.540 /usr/lib64/python3.12/site-packages/pyanaconda/core/threads.py:274(run)
    28/19    0.008    0.000    1.076    0.057 {method 'acquire' of '_thread.lock' objects}
      8/3    0.000    0.000    1.069    0.356 /usr/lib64/python3.12/site-packages/pyanaconda/core/threads.py:102(wait)
        1    0.000    0.000    1.069    1.069 /usr/lib64/python3.12/site-packages/pyanaconda/ui/webui/__init__.py:69(setup)
      3/2    0.000    0.000    1.069    0.534 /usr/lib64/python3.12/threading.py:1094(join)
        1    0.000    0.000    1.069    1.069 /usr/lib64/python3.12/site-packages/pyanaconda/core/threads.py:126(wait_all)
      3/2    0.000    0.000    1.068    0.534 /usr/lib64/python3.12/threading.py:1132(_wait_for_tstate_lock)
      4/2    0.000    0.000    1.045    0.522 /usr/lib64/python3.12/threading.py:978(run)
        1    0.000    0.000    1.032    1.032 /usr/lib64/python3.12/site-packages/pyanaconda/payload/manager.py:105(_task_run_callback)
        1    0.000    0.000    1.032    1.032 /usr/lib64/python3.12/site-packages/pyanaconda/payload/manager.py:133(_run)
        1    0.000    0.000    0.897    0.897 /usr/lib64/python3.12/site-packages/pyanaconda/ui/lib/storage.py:79(reset_storage)
        1    0.000    0.000    0.572    0.572 /usr/lib64/python3.12/site-packages/pyanaconda/startup_utils.py:409(parse_kickstart)
      616    0.006    0.000    0.536    0.001 <frozen importlib._bootstrap_external>:1061(get_code)
        1    0.000    0.000    0.523    0.523 /usr/lib64/python3.12/site-packages/pyanaconda/kickstart.py:322(parseKickstart)
6586/6470    0.444    0.000    0.498    0.000 {method 'read' of '_io.BufferedReader' objects}
        1    0.000    0.000    0.464    0.464 /usr/lib64/python3.12/site-packages/pyanaconda/core/util.py:1(<module>)
      616    0.002    0.000    0.446    0.001 <frozen importlib._bootstrap_external>:1182(get_data)
        1    0.001    0.001    0.432    0.432 /usr/lib64/python3.12/site-packages/pyanaconda/core/startup/dbus_launcher.py:61(start)
        2    0.000    0.000    0.284    0.142 /usr/lib64/python3.12/site-packages/pyanaconda/kickstart.py:250(__init__)
        2    0.000    0.000    0.284    0.142 /usr/lib/python3.12/site-packages/pykickstart/base.py:463(__init__)
        2    0.000    0.000    0.284    0.142 /usr/lib/python3.12/site-packages/pykickstart/base.py:542(_registerCommands)
        1    0.000    0.000    0.283    0.283 /usr/lib64/python3.12/site-packages/pyanaconda/core/startup/dbus_launcher.py:197(_start_boss)
        1    0.000    0.000    0.280    0.280 /usr/lib64/python3.12/site-packages/pyanaconda/startup_utils.py:160(set_storage_checker_minimal_ram_size)
   636158    0.167    0.000    0.264    0.000 /usr/lib/python3.12/site-packages/langtable/langtable.py:219(characters)
        1    0.000    0.000    0.259    0.259 /usr/lib64/python3.12/site-packages/pyanaconda/startup_utils.py:400(run_pre_scripts)
        1    0.000    0.000    0.259    0.259 /usr/lib64/python3.12/site-packages/pyanaconda/kickstart.py:309(preScriptPass)
        1    0.000    0.000    0.247    0.247 /usr/lib/python3.12/site-packages/requests/__init__.py:1(<module>)
    73/57    0.000    0.000    0.239    0.004 /usr/lib64/python3.12/importlib/__init__.py:73(import_module)
    73/57    0.000    0.000    0.239    0.004 <frozen importlib._bootstrap>:1281(_gcd_import)
        1    0.000    0.000    0.218    0.218 /usr/lib64/python3.12/site-packages/pyanaconda/ui/lib/storage.py:385(ignore_oemdrv_disks)
        1    0.000    0.000    0.218    0.218 /usr/lib64/python3.12/site-packages/pyanaconda/core/storage.py:139(device_matches)
        1    0.001    0.001    0.203    0.203 /usr/lib/python3.12/site-packages/pykickstart/handlers/control.py:1(<module>)
        1    0.000    0.000    0.194    0.194 /usr/lib/python3.12/site-packages/blivet/udev.py:142(resolve_devspec)
  690/659    0.007    0.000    0.173    0.000 <frozen importlib._bootstrap>:1146(_find_spec)
        1    0.000    0.000    0.170    0.170 /usr/lib/python3.12/site-packages/blivet/devices/__init__.py:1(<module>)
1997/1992    0.041    0.000    0.158    0.000 {built-in method builtins.__build_class__}
        1    0.000    0.000    0.136    0.136 /usr/lib/python3.12/site-packages/urllib3/__init__.py:1(<module>)
        1    0.000    0.000    0.132    0.132 /usr/lib64/python3.12/site-packages/pyanaconda/payload/live/payload_liveos.py:32(set_from_opts)
        1    0.000    0.000    0.111    0.111 /usr/lib64/python3.12/site-packages/pyanaconda/core/startup/dbus_launcher.py:202(_start_modules)
        1    0.000    0.000    0.107    0.107 /usr/lib/python3.12/site-packages/blivet/devices/storage.py:1(<module>)
        1    0.000    0.000    0.107    0.107 /usr/lib64/python3.12/site-packages/pyanaconda/payload/migrated.py:74(setup)
        1    0.000    0.000    0.107    0.107 /usr/lib64/python3.12/site-packages/pyanaconda/ui/lib/payload.py:120(set_up_sources)
        1    0.000    0.000    0.104    0.104 /usr/lib64/python3.12/site-packages/pyanaconda/core/configuration/anaconda.py:1(<module>)
        1    0.000    0.000    0.103    0.103 /usr/lib/python3.12/site-packages/blivet/formats/__init__.py:1(<module>)

Comment 10 Ray Strode [halfline] 2023-08-31 20:41:26 UTC
so we can see a ton of time is just spent on import calls. 

I don't know how we can optimize that.

Next in the profile is synchronous dbus calls. There's 88 of them but they add up to 2.3 seconds of start up time. We might be able to make some of them async, but given the number of calls it might be hard to make in roads.

Next up is langtable. it's parsing a large amount of xml data and that's taking a significant chunk of time. maybe we can skip that on live images since we aren't asking for language or keyboard from anaconda.

Comment 11 Jiri Konecny 2023-09-01 12:03:26 UTC
*** Bug 2232635 has been marked as a duplicate of this bug. ***

Comment 12 Adam Williamson 2023-09-02 00:14:44 UTC
I feel like this should be fixed at Beta if possible too, though not if it involves too risky a change.

Comment 13 Allan Day 2023-09-04 14:14:42 UTC
I just tested F38 to see how the new UI compares to the old GTK one.

In F38, there's around a 9 second delay between clicking "Install Fedora..." and the installer window appearing. Crucially, during that time the pointer has a spinner state, so you know that something is going on.

Comment 14 Adam Williamson 2023-09-04 15:47:07 UTC
+3 in https://pagure.io/fedora-qa/blocker-review/issue/1242 , marking accepted FE.

Comment 15 František Zatloukal 2023-09-04 18:10:13 UTC
Discussed during the 2023-09-04 blocker review meeting: [1]

The decision to classify this bug as a RejectedBlocker (Final) was made:

"We agree that ideally anaconda should start faster and/or the user should get some feedback indicating it's loading, but this really doesn't take long enough to plausibly constitute a release blocker. note it's already accepted as Beta FE."

[1] https://meetbot-raw.fedoraproject.org/fedora-blocker-review/2023-09-04/f39-blocker-review.2023-09-04-16.00.log.txt

Comment 16 Adam Williamson 2023-09-12 22:19:29 UTC
As webUI has been deferred to F40, deferring the FE status of this bug.

Comment 17 Kamil Páral 2023-09-15 08:27:36 UTC
Since this has been deferred to F40 and might change in the meantime, removing the CommonBugs nomination at this moment.

Comment 19 Jiri Konecny 2024-01-23 12:17:17 UTC
From my testing the improvement seems to be a bit less then 50% faster startup.

If it is still not enough then we need to improve Firefox startup time because it's started even before Anaconda is. From Anaconda PoV we can't do much more.

Comment 20 Adam Williamson 2024-01-23 16:48:39 UTC
Thanks!

Is there any possibility to show a spinner or something while Firefox is loading? That was one of the initial notes (that with the old way we got a spinner during load).

Comment 21 Jiri Konecny 2024-01-24 10:54:41 UTC
Implemented here: https://github.com/rhinstaller/anaconda-webui/pull/132

In general this should be tested together with anaconda-webui-4-1

Comment 22 Adam Williamson 2024-02-07 20:25:54 UTC
So I tested this on today's Workstation live, on my not-particularly-fast laptop (last gen XPS 13). From clicking the install button to seeing a window appear (not yet fully populated) was 15 seconds. A spinner was shown briefly. Then I tested again and got 11 seconds, but didn't see a spinner.

So, it's definitely better but not entirely "fixed". Hard to say if it's "good enough". A spinner would be nice if it's possible...

Comment 23 Adam Williamson 2024-03-01 21:28:56 UTC
As this is a webUI-specific issue, it doesn't make sense to track it as an FE for F40 any more. Bumping to Rawhide and clearing blocker/FE metadata.


Note You need to log in before you can comment on or make changes to this bug.