Received-SPF: pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 2620:137:e000::1:20 as permitted sender) client-ip=2620:137:e000::1:20;
Message-ID: <cb149b17-4bbf-71b0-424c-c4f3d1b96952@suse.com>
Date:   Wed, 7 Dec 2022 14:23:25 +0100
User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:91.0) Gecko/20100101
 Thunderbird/91.12.0
Subject: Re: [PATCH v2 2/2] module: Merge same-name module load requests
Content-Language: en-US
To:     Prarit Bhargava <prarit@redhat.com>, Petr Mladek <pmladek@suse.com>
Cc:     David Hildenbrand <david@redhat.com>,
        Luis Chamberlain <mcgrof@kernel.org>,
        linux-modules@vger.kernel.org, linux-kernel@vger.kernel.org
References: <YzdR0gRNQI2BGnJ9@bombadil.infradead.org>
 <aa8d9456-b260-d999-0296-8e6ab876af7a@suse.com>
 <Y07xX2ejlg0oFoEy@bombadil.infradead.org>
 <d0bc50e3-0e42-311b-20ed-7538bb918c5b@suse.com>
 <Y277Jb9i2VeXQoTL@bombadil.infradead.org>
 <e070839f-c224-047b-9411-91143c1d8394@redhat.com>
 <Y3Jg8X7qv2AKPU1J@bombadil.infradead.org>
 <5467e66d-55de-ca8f-c1ae-ffe6efe7290d@redhat.com>
 <94cd5565-1058-2c97-57bb-0ddf12416cd6@redhat.com>
 <2ac0b871-60d0-c535-3fe0-bfaa0d9f7685@suse.com> <Y4opfN6MTsFhrYfu@alley>
 <2e8d862d-fa3d-0879-9097-215d17cb1fed@redhat.com>
From:   Petr Pavlu <petr.pavlu@suse.com>
In-Reply-To: <2e8d862d-fa3d-0879-9097-215d17cb1fed@redhat.com>
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 7bit
MIME-Version: 1.0
X-MS-Exchange-AntiSpam-MessageData-ChunkCount: 1
X-MS-Exchange-AntiSpam-MessageData-0: =?utf-8?B?OHVIZzBidVlUUFdiQk9YMGxHM3lXSXAvOTJyQmdyV21kNlFGMENvTFJJQXVJ?=
 =?utf-8?B?dGtNN2locUJZV1RQQnBkeUU5V3VaVG5VQ2c0cjU2TWdCUmVuRUpGaFFCdFV3?=
 =?utf-8?B?RG52N3Z4WDhFd0lBU3Bqc3dsWVZFbXU0YTlFdDJ5T2pLVVdmdVRoTE9SOWJS?=
 =?utf-8?B?dHIxRExXNTZzd251eDROK1UydURKNW9TMHU1djlLa2JYaGR3QzZIenhJWTcw?=
 =?utf-8?B?MlZZZ0UyUzF0UkdDQ0ErUUszR0dhMXZRMzdlY3ZUSkNXc29tMWlKSGQ0U1o4?=
 =?utf-8?B?VzN0UjRQcHB3SUs5aGlMTkhjMXVDaUVPNkVzN3cyOTZ5elRjdVNSM0ZXL1Vy?=
 =?utf-8?B?YmFPZHEwWG81OEtFa1d1SFNjWXNGTGtpTjFPdVdaN3hKWHlLeWVJU2F1UUpF?=
 =?utf-8?B?WnBvQWlKZkRUUW83NWdLZGFid3BEVjcra243NmVCQXcwWnhuakV0RU13TmpO?=
 =?utf-8?B?VzJ4L3l5VTNBRG1mQSsxb0pZZjREMm1CS0t6NmRPd2Z2Nkp4cXdFanNaZ1h3?=
 =?utf-8?B?cmNXK21iVjhMWm10OE5Jc2gwVG10bFRqdWV1UGdiRGNmWnBHSFdpZVpQTnox?=
 =?utf-8?B?MjNTYmRRVTBYWUZSRVJDK1FucmFqN0hrVzRyZWJsU0hDbWwxTGwzemxHZFRz?=
 =?utf-8?B?Z2VTVHZiOGJ5Y2dJNXZuNjErUkFwdnhsYUNMTGNNS3NSeGpHSStXU3pjeERq?=
 =?utf-8?B?OGVYOVFmcWd4a2w0MTV4UXc0MTVFeG9oWEVUYUFEbTliMzZQUHZoN1dUL21q?=
 =?utf-8?B?SGF2ZDhDUXorYnhYTUk5dzBWODJ3MUFnT2pnNS9iREZSeG5tNUJ0VGNtRlla?=
 =?utf-8?B?RDFFWGNZWnRxcHJrRHkwekxINVkvbVNBWTdGVjJVSWtLM25xTjFOamtCczlK?=
 =?utf-8?B?Y2t2OEdCOCs4UHp1S0NLYWF0cjRhTDRWdEpaL2xpbnpTL0FCZis4T05tQkd5?=
 =?utf-8?B?b3pHNXJqSjcwN3UyLzVpcUV6SVVzR3RoKzZWc05qbzVQemtsaVJiV0QwckFC?=
 =?utf-8?B?UEduWEZZL2dZNWZqV1I4SVFDcExSM1BMQVJXbWsyUnV3bjFTQ09pbmVlWXZS?=
 =?utf-8?B?RTZBa3ZJT3Z3OVR5cE13RUNGV3pMbjBYcnRwNEZHWXZmRWdyN29ZaXdiVmRq?=
 =?utf-8?B?WG01Vys1dXVlelZYbndqL1VLSjJ6bVFCa1lQNDhVeTlKWkVra0hzMzJHZlZP?=
 =?utf-8?B?OG1NUmRWMnp4NHBramxjYUtIQXNWR0ladnpBZkxPTlBQQ0hWUEpCUk9jWVI1?=
 =?utf-8?B?R1VLSXRXeDJybjZxWWY0MlBpY3Q2TGk1Qk8xZnZLQXhHSUNWbGtucnY5TUc5?=
 =?utf-8?B?d2NRbmVVRTZYSlBZQnlLa090aWw4eDdZYzBPVWxzMjNRZGtTR3MrT0NVZEJW?=
 =?utf-8?B?bHpkanZwNUZuZHFtME9rMitHSE0rOGtNVWliZSt1OEpKNWlKbWxCdy9uTlNa?=
 =?utf-8?B?NDRVTFFoRVhGaFVBTG5xMThKQjd2ejR3ZEUrK3JoS1NOZmdqbmZYSUlQdkFB?=
 =?utf-8?B?Y3JmVGU0aWNLbnoxOVkxRDhmN0ZmYlovYUJOaXd2dllPa2huSXNqUnFaRkw0?=
 =?utf-8?B?a2JsMXpKU2FoVVBwMWJRMmluUFlQcXVyWm9ZdU5lM2JkdVR3Q2ZmVDNLWHVh?=
 =?utf-8?B?OFBDT01xT1VzNFdGTWdld0N6KzZFS29SQlpuTjFjVW5jU0dFNHNmTDZLK2l3?=
 =?utf-8?B?S1ljbDkvTVNSY0JMOEFTelMzOEVGaGd5TVBXZ0dmY1pvUk84RnN0SzlkQVBs?=
 =?utf-8?B?N2JlNXVIaFhqT2Q0VCs1ajFUMHRHOFZWaDl0MG83aDF0NmEwOTB5Y2ZVdWlX?=
 =?utf-8?B?bUZ0dmNQYnlwKzgrS0szL0pMaUtmQURuQlVOY3RXOFUzNFQ1SHpBVGFjMitq?=
 =?utf-8?B?OWJHTC9iU3ltRWkrYklQU2lHYmwrTWpuMEhodjBsRnVQQVdIU2ZzT2Jnejho?=
 =?utf-8?B?MFRGSHpVNWJnV28vNm1oY0YzSkxTaFZSVHVNMzdYNU11VkE0aHRKdVM1RUJn?=
 =?utf-8?B?MS9EV29VTXVuOTI5WW1yNnNNSXo0SWVkcmErZnBoOFVRcW1OS1NjaEIzdGto?=
 =?utf-8?B?dHpodjZJMXZ1UEZDS3F0YXVpK0JMemdacWZNV0tDbTBnTTJJc0wyK2c3eTFk?=
 =?utf-8?Q?/XCwynPZKqEAyiKg2EnqVaQae?=
X-OriginatorOrg: suse.com
X-MS-Exchange-CrossTenant-Network-Message-Id: 3a05486c-fa36-47cf-3290-08dad8563950
X-MS-Exchange-CrossTenant-AuthSource: VI1PR0402MB3406.eurprd04.prod.outlook.com
X-MS-Exchange-CrossTenant-AuthAs: Internal
X-MS-Exchange-CrossTenant-OriginalArrivalTime: 07 Dec 2022 13:23:27.0284
 (UTC)
X-MS-Exchange-CrossTenant-FromEntityHeader: Hosted
X-MS-Exchange-CrossTenant-Id: f7a17af6-1c5c-4a36-aa8b-f5be247aa4ba
X-MS-Exchange-CrossTenant-MailboxType: HOSTED
X-MS-Exchange-CrossTenant-UserPrincipalName: aI/k/42RPRgF5peBJL46+FLQa1o6ErKSMKBGUNSWBZGQWVjBF6qKy00D0hNNUXLSrNzP1s6Qo+4YBAcG+jjZDg==
X-MS-Exchange-Transport-CrossTenantHeadersStamped: PAXPR04MB9376
X-Spam-Status: No, score=-2.4 required=5.0 tests=BAYES_00,DKIM_SIGNED,
        DKIM_VALID,DKIM_VALID_AU,DKIM_VALID_EF,NICE_REPLY_A,RCVD_IN_DNSWL_NONE,
        RCVD_IN_MSPIKE_H2,SPF_HELO_PASS,SPF_PASS autolearn=ham
        autolearn_force=no version=3.4.6
X-Spam-Checker-Version: SpamAssassin 3.4.6 (2021-04-09) on
        lindbergh.monkeyblade.net
Precedence: bulk
List-ID: <linux-kernel.vger.kernel.org>
X-Mailing-List: linux-kernel@vger.kernel.org

On 12/6/22 13:31, Prarit Bhargava wrote:
> 
>>
>>> Could you please boot the machine with 'udev.log_level=debug' and provide me
>>> logs ('journalctl -b -o short-monotonic') from a run with the vanilla kernel
>>> and with the discussed patch?
>>
> 
> Petr, I tried to in-line the logs however the email bounced due to its size.
> 
> I know this isn't a preferred method of passing information on LKML and 
> other lists, but here are links to the logs:
> 
> https://people.redhat.com/prarit/4petr/
> 
> Both outputs were done with, as requested, 'journalctl -b -o 
> short-monotonic'.
> 
> vanilla.log is kernel booted with 'udev.log_level=debug'
> with-changeset.log is kernel + patch booted with 'udev.log_level=debug'

Thanks Prarit for re-testing the patch. Both logs in this case actually show
similar startup times.

Vanilla:
[   68.108176] intel-eaglestream-spr-15.khw3.lab.eng.bos.redhat.com systemd[1]: Startup finished in 55.874s (firmware) + 25.646s (loader) + 35.793s (kernel) + 7.845s (initrd) + 24.469s (userspace) = 2min 29.629s.

With the patch:
[   68.064826] intel-eaglestream-spr-15.khw3.lab.eng.bos.redhat.com systemd[1]: Startup finished in 54.153s (firmware) + 19.947s (loader) + 35.965s (kernel) + 9.449s (initrd) + 22.650s (userspace) = 2min 22.165s.


The system has 192 CPUs. The vanilla case shows 144x inserts of acpi_cpufreq
and 43x of pcc_cpufreq:

acpi_cpufreq (the first and last recorded insert):
[   47.485621] intel-eaglestream-spr-15.khw3.lab.eng.bos.redhat.com systemd-udevd[1871]: Inserted module 'acpi_cpufreq'
[...]
[   53.052401] intel-eaglestream-spr-15.khw3.lab.eng.bos.redhat.com systemd-udevd[1914]: Inserted module 'acpi_cpufreq'

pcc_cpufreq:
[   47.515221] intel-eaglestream-spr-15.khw3.lab.eng.bos.redhat.com systemd-udevd[1871]: Inserted module 'pcc_cpufreq'
[...]
[   53.067917] intel-eaglestream-spr-15.khw3.lab.eng.bos.redhat.com systemd-udevd[2040]: Inserted module 'pcc_cpufreq'

Processing inserts of all CPU frequency modules took at least ~5.5 seconds.
It was likely more because not all inserts are recorded in the log, udevd
messages appear to be missing from ~53.1.


With the patch, both modules are attempted to be inserted 192x:

acpi_cpufreq:
[   50.107403] intel-eaglestream-spr-15.khw3.lab.eng.bos.redhat.com systemd-udevd[1817]: Failed to insert module 'acpi_cpufreq': Device or resource busy
[...]
[   50.438755] intel-eaglestream-spr-15.khw3.lab.eng.bos.redhat.com systemd-udevd[2016]: Inserted module 'acpi_cpufreq'

pcc_cpufreq:
[   50.110731] intel-eaglestream-spr-15.khw3.lab.eng.bos.redhat.com systemd-udevd[1849]: Failed to insert module 'pcc_cpufreq': Device or resource busy
[...]
[   50.579249] intel-eaglestream-spr-15.khw3.lab.eng.bos.redhat.com systemd-udevd[2016]: Inserted module 'pcc_cpufreq'

This shows that the patch reduced the sequence to ~0.5 seconds and its logic
looks to be working as intended.

Thanks,
Petr