Monday, June 25, 2018

Boot time differences

Fast boot with the master kernel (4.18.0-rc1+), but very limited set of systemd services started: see 180625-fast-boot.txt. demsg ends with:

[    5.147579] NFS: bad mount option value specified: minorversion=1
[    5.166608] mount.nfs (3068) used greatest stack depth: 12016 bytes left

Much slower boot with Fedora 4.16 (minutes): 180625-slow-kernel.txt. The dmesg part that talks about NFS happens around 235 seconds:

[  235.263894] NFS: Registering the id_resolver key type

One of the odd things I noticed in the log is:

[    5.467516] systemd-journald[214]: Received SIGTERM from PID 1 (systemd).
[    6.109459] systemd: 17 output lines suppressed due to ratelimiting

That seems a bit similar to Red Hat Bugzilla 1378779

The boot time is also extremely variable. Something is seriously messed up with that system.

NVIDIA driver build error with version 396.24, missing DRM_CONTROL_ALLOW:

  CC [M]  /tmp/selfgz4801/NVIDIA-Linux-x86_64-396.24/kernel/nvidia-drm/nv-pci-table.o
In file included from /home/ddd/Work/linux/include/drm/drmP.h:82,
                 from /tmp/selfgz4801/NVIDIA-Linux-x86_64-396.24/kernel/nvidia-drm/nvidia-drm-priv.h:30,
                 from /tmp/selfgz4801/NVIDIA-Linux-x86_64-396.24/kernel/nvidia-drm/nvidia-drm-drv.c:25:
/tmp/selfgz4801/NVIDIA-Linux-x86_64-396.24/kernel/nvidia-drm/nvidia-drm-drv.c:637:23: error: ‘DRM_CONTROL_ALLOW’ undeclared here (not in a function); did you mean ‘DRM_RENDER_ALLOW’?
                       DRM_CONTROL_ALLOW|DRM_RENDER_ALLOW|DRM_UNLOCKED),
                       ^~~~~~~~~~~~~~~~~
/home/ddd/Work/linux/include/drm/drm_ioctl.h:162:12: note: in definition of macro ‘DRM_IOCTL_DEF_DRV’
   .flags = _flags,
            ^~~~~~

No longer have a problem with API mismatch after multiple reinstallations of the NVIDIA driver, but still fails after only about 10 seconds with an error 2:

ddd@f25-turbo ~> DISPLAY=:1 RECORDER_TRACES='plugins:nvidia.*:main' spice-streaming-agent
[58 0.000163] main: Entering SPICE streaming agent spice-streaming-agent with 1 args
[59 0.000256] plugins: Loading plugins from /usr/local/lib/spice-streaming-agent/plugins/*.so
[60 0.000461] plugins: Plugin 1/1 is /usr/local/lib/spice-streaming-agent/plugins/libnvidia.so
[61 0.000481] plugins: Loading /usr/local/lib/spice-streaming-agent/plugins/libnvidia.so
[62 0.001518] plugins: Plugin init function is 0x7f138f5a2d15
[82 0.000126] nvidia: Streaming agent plugin recorded
[63 0.003257] main: Read header type 1
[64 0.003276] main: Reading capabilities len 0
[65 0.003281] main: Writing capabilities size 8
[66 0.003307] main: Wrote capabilities
[67 0.003322] main: Read header type 4
[69 0.003345] plugins: Plugin 0xa5dcc0 has rank 1
[70 0.003354] plugins: Plugin 0xa5da80 has rank -1073741824
[76 0.003367] plugins: Plugin 0xa5da80 offers codec type 3
[83 0.001880] nvidia: Create capture
[84 3.978123] nvidia: Capture frame
[85 3.978150] nvidia: Release frame
[86 3.978156] nvidia_sleep: Did sleep for 33333 us
[87 4.011657] nvidia: Check setting updates
[88 4.011693] nvidia: Start streaming
[89 4.045908] nvidia: Create capture session
[90 4.871228] nvidia_init: Releasing encoder
[91 4.871257] nvidia: Release encoder
[92 4.871262] nvidia: Release frame
[93 4.871266] nvidia_init: Recording initial settings
[94 4.871270] nvidia_init: Create encoder session
[95 9.889692] nvidia: Reset capture
[96 9.889725] nvidia: Release encoder
[97 9.889730] nvidia: Release frame
spice-streaming-agent[8370]: nvEncOpenEncodeSessionEx failed(2)

The run right after that works quite well:

ddd@f25-turbo ~> DISPLAY=:1 RECORDER_TRACES='plugins:nvidia.*:main' spice-streaming-agent
[58 0.000133] main: Entering SPICE streaming agent spice-streaming-agent with 1 args
[59 0.000216] plugins: Loading plugins from /usr/local/lib/spice-streaming-agent/plugins/*.so
[60 0.000518] plugins: Plugin 1/1 is /usr/local/lib/spice-streaming-agent/plugins/libnvidia.so
[61 0.000540] plugins: Loading /usr/local/lib/spice-streaming-agent/plugins/libnvidia.so
[62 0.002842] plugins: Plugin init function is 0x7f1a44b79d15
[82 0.000528] nvidia: Streaming agent plugin recorded
[63 0.006669] main: Read header type 1
[64 0.006689] main: Reading capabilities len 0
[65 0.006694] main: Writing capabilities size 8
[66 0.006708] main: Wrote capabilities
[67 0.006791] main: Read header type 4
[69 0.006895] plugins: Plugin 0x1390cc0 has rank 1
[70 0.006914] plugins: Plugin 0x1390a80 has rank -1073741824
[76 0.006989] plugins: Plugin 0x1390a80 offers codec type 3
[83 0.004188] nvidia: Create capture
[84 0.113465] nvidia: Capture frame
[85 0.113491] nvidia: Release frame
[86 0.113497] nvidia_sleep: Did sleep for 33333 us
[87 0.147111] nvidia: Check setting updates
[88 0.147133] nvidia: Start streaming
[89 0.181443] nvidia: Create capture session
[90 0.240373] nvidia_init: Releasing encoder
[91 0.240398] nvidia: Release encoder
[92 0.240403] nvidia: Release frame
[93 0.240407] nvidia_init: Recording initial settings
[94 0.240411] nvidia_init: Create encoder session
[95 0.521363] nvidia_init: Validate encoder GUID
[96 0.521535] nvidia_init: Initialize encode session
[97 0.531085] nvidia_init: Register texture
[98 0.531118] nvidia_init: Register parameters
[99 0.531756] nvidia_init: Create bitstream buffer
[100 0.533273] nvidia_init: Done
[101 0.533305] nvidia: Stream started
[102 0.533321] nvidia: Grab first frame
[103 0.533334] nvidia: FBC to GL grab frame
[104 0.571904] nvidia: Map frame for use by encoder
[105 0.572209] nvidia: Fill frame encoding information
[106 0.572240] nvidia: Encode the frame
[107 0.574056] nvidia: Get the bitstream
[108 0.580323] nvidia_frames: Capture 343799.92 bytes/s, total 199515, 1.72 loops/s, avg duration 80992.83 us,
[109 0.580359] nvidia_capture: Captured 199515 bytes after 580.358000 ms, 1600 x 1200 pixels
[110 0.580481] nvidia: Capture frame
[111 0.580506] nvidia: Release frame
[112 0.580519] nvidia: Unlock bitstream
[113 0.580530] nvidia: Unmap input resource
[114 0.580799] nvidia_sleep: Did not sleep, behind by -400636 us
[115 0.580829] nvidia: Check setting updates
[116 0.580853] nvidia: Grab another frame
[117 0.580984] nvidia: FBC to GL grab frame
[118 0.581169] nvidia: Map frame for use by encoder
[119 0.581444] nvidia: Fill frame encoding information
[120 0.581481] nvidia: Encode the frame
[121 0.581635] nvidia: Get the bitstream
[122 0.584620] nvidia_frames: Capture 42597.77 bytes/s, total 199698, 232.77 loops/s, avg duration 876629.42 us,
[123 0.584650] nvidia_capture: Captured 183 bytes after 4.292000 ms, 1600 x 1200 pixels
[124 0.584689] nvidia: Capture frame
[125 0.584703] nvidia: Release frame
[126 0.584714] nvidia: Unlock bitstream
[127 0.584727] nvidia: Unmap input resource
[128 0.584903] nvidia_sleep: Did sleep for 29229 us
[129 0.614269] nvidia: Check setting updates
[130 0.614304] nvidia: Grab another frame
[131 0.614326] nvidia: FBC to GL grab frame
[132 0.614445] nvidia: Map frame for use by encoder
[133 0.614648] nvidia: Fill frame encoding information
[134 0.614679] nvidia: Encode the frame
[135 0.614869] nvidia: Get the bitstream
[136 0.617815] nvidia_frames: Capture 2952.16 bytes/s, total 199796, 30.12 loops/s, avg duration 105765.75 us,
[137 0.617852] nvidia_capture: Captured 98 bytes after 33.202000 ms, 1600 x 1200 pixels
[138 0.617892] nvidia: Capture frame
[139 0.617907] nvidia: Release frame
[140 0.617919] nvidia: Unlock bitstream
[141 0.617932] nvidia: Unmap input resource
[142 0.618126] nvidia_sleep: Did sleep for 29339 us
[143 0.647578] nvidia: Check setting updates
[144 0.647603] nvidia: Grab another frame
[145 0.647610] nvidia: FBC to GL grab frame
[146 0.647737] nvidia: Map frame for use by encoder
[147 0.647949] nvidia: Fill frame encoding information
[148 0.647969] nvidia: Encode the frame
[149 0.648163] nvidia: Get the bitstream
[150 0.651103] nvidia_frames: Capture 3995.43 bytes/s, total 199929, 30.04 loops/s, avg duration 105142.99 us,
[151 0.651126] nvidia_capture: Captured 133 bytes after 33.274000 ms, 1600 x 1200 pixels
[152 0.651153] nvidia: Capture frame
[153 0.651162] nvidia: Release frame
[154 0.651166] nvidia: Unlock bitstream
[155 0.651172] nvidia: Unmap input resource
[156 0.651339] nvidia_sleep: Did sleep for 29459 us
...
[7436 17.984489] nvidia_sleep: Did sleep for 29468 us
[7437 18.014074] nvidia: Check setting updates
[7438 18.014098] nvidia: Grab another frame
[7439 18.014110] nvidia: FBC to GL grab frame
^C[7440 18.014187] nvidia: Map frame for use by encoder
[7441 18.014366] nvidia: Fill frame encoding information
[7442 18.014398] nvidia: Encode the frame
[7443 18.014562] nvidia: Get the bitstream
[7444 18.017714] nvidia_frames: Capture 50149.43 bytes/s, total 5025677, 29.89 loops/s, avg duration 108099.22 us,
[7445 18.017749] nvidia_capture: Captured 1678 bytes after 33.467000 ms, 1600 x 1200 pixels
[7446 18.017779] nvidia: Reset capture
[7447 18.017790] nvidia: Release encoder
[7448 18.017798] nvidia: Release frame
[7449 18.017806] nvidia: Unlock bitstream
[7450 18.017815] nvidia: Unmap input resource
[7451 18.017969] nvidia: Unregister resource
[7452 18.019196] nvidia: Destroy bitstream buffer
[7453 18.019767] nvidia: Destroy encoder
[7454 18.051056] nvidia: Destroy capture session
[7455 18.052186] nvidia: Release encoder
[7456 18.052216] nvidia: Release frame

It's the same binary with the same command line, just two different runs.