1 // SPDX-License-Identifier: GPL-2.0-or-later 2 /* 3 * Debugging module statistics. 4 * 5 * Copyright (C) 2023 Luis Chamberlain <mcgrof@kernel.org> 6 */ 7 8 #include <linux/module.h> 9 #include <uapi/linux/module.h> 10 #include <linux/string.h> 11 #include <linux/printk.h> 12 #include <linux/slab.h> 13 #include <linux/list.h> 14 #include <linux/debugfs.h> 15 #include <linux/rculist.h> 16 #include <linux/math.h> 17 18 #include "internal.h" 19 20 /** 21 * DOC: module debugging statistics overview 22 * 23 * Enabling CONFIG_MODULE_STATS enables module debugging statistics which 24 * are useful to monitor and root cause memory pressure issues with module 25 * loading. These statistics are useful to allow us to improve production 26 * workloads. 27 * 28 * The current module debugging statistics supported help keep track of module 29 * loading failures to enable improvements either for kernel module auto-loading 30 * usage (request_module()) or interactions with userspace. Statistics are 31 * provided to track all possible failures in the finit_module() path and memory 32 * wasted in this process space. Each of the failure counters are associated 33 * to a type of module loading failure which is known to incur a certain amount 34 * of memory allocation loss. In the worst case loading a module will fail after 35 * a 3 step memory allocation process: 36 * 37 * a) memory allocated with kernel_read_file_from_fd() 38 * b) module decompression processes the file read from 39 * kernel_read_file_from_fd(), and vmap() is used to map 40 * the decompressed module to a new local buffer which represents 41 * a copy of the decompressed module passed from userspace. The buffer 42 * from kernel_read_file_from_fd() is freed right away. 43 * c) layout_and_allocate() allocates space for the final resting 44 * place where we would keep the module if it were to be processed 45 * successfully. 46 * 47 * If a failure occurs after these three different allocations only one 48 * counter will be incremented with the summation of the allocated bytes freed 49 * incurred during this failure. Likewise, if module loading failed only after 50 * step b) a separate counter is used and incremented for the bytes freed and 51 * not used during both of those allocations. 52 * 53 * Virtual memory space can be limited, for example on x86 virtual memory size 54 * defaults to 128 MiB. We should strive to limit and avoid wasting virtual 55 * memory allocations when possible. These module debugging statistics help 56 * to evaluate how much memory is being wasted on bootup due to module loading 57 * failures. 58 * 59 * All counters are designed to be incremental. Atomic counters are used so to 60 * remain simple and avoid delays and deadlocks. 61 */ 62 63 /** 64 * DOC: dup_failed_modules - tracks duplicate failed modules 65 * 66 * Linked list of modules which failed to be loaded because an already existing 67 * module with the same name was already being processed or already loaded. 68 * The finit_module() system call incurs heavy virtual memory allocations. In 69 * the worst case an finit_module() system call can end up allocating virtual 70 * memory 3 times: 71 * 72 * 1) kernel_read_file_from_fd() call uses vmalloc() 73 * 2) optional module decompression uses vmap() 74 * 3) layout_and allocate() can use vzalloc() or an arch specific variation of 75 * vmalloc to deal with ELF sections requiring special permissions 76 * 77 * In practice on a typical boot today most finit_module() calls fail due to 78 * the module with the same name already being loaded or about to be processed. 79 * All virtual memory allocated to these failed modules will be freed with 80 * no functional use. 81 * 82 * To help with this the dup_failed_modules allows us to track modules which 83 * failed to load due to the fact that a module was already loaded or being 84 * processed. There are only two points at which we can fail such calls, 85 * we list them below along with the number of virtual memory allocation 86 * calls: 87 * 88 * a) FAIL_DUP_MOD_BECOMING: at the end of early_mod_check() before 89 * layout_and_allocate(). 90 * - with module decompression: 2 virtual memory allocation calls 91 * - without module decompression: 1 virtual memory allocation calls 92 * b) FAIL_DUP_MOD_LOAD: after layout_and_allocate() on add_unformed_module() 93 * - with module decompression 3 virtual memory allocation calls 94 * - without module decompression 2 virtual memory allocation calls 95 * 96 * We should strive to get this list to be as small as possible. If this list 97 * is not empty it is a reflection of possible work or optimizations possible 98 * either in-kernel or in userspace. 99 */ 100 static LIST_HEAD(dup_failed_modules); 101 102 /** 103 * DOC: module statistics debugfs counters 104 * 105 * The total amount of wasted virtual memory allocation space during module 106 * loading can be computed by adding the total from the summation: 107 * 108 * * @invalid_kread_bytes + 109 * @invalid_decompress_bytes + 110 * @invalid_becoming_bytes + 111 * @invalid_mod_bytes 112 * 113 * The following debugfs counters are available to inspect module loading 114 * failures: 115 * 116 * * total_mod_size: total bytes ever used by all modules we've dealt with on 117 * this system 118 * * total_text_size: total bytes of the .text and .init.text ELF section 119 * sizes we've dealt with on this system 120 * * invalid_kread_bytes: bytes allocated and then freed on failures which 121 * happen due to the initial kernel_read_file_from_fd(). kernel_read_file_from_fd() 122 * uses vmalloc(). These should typically not happen unless your system is 123 * under memory pressure. 124 * * invalid_decompress_bytes: number of bytes allocated and freed due to 125 * memory allocations in the module decompression path that use vmap(). 126 * These typically should not happen unless your system is under memory 127 * pressure. 128 * * invalid_becoming_bytes: total number of bytes allocated and freed used 129 * to read the kernel module userspace wants us to read before we 130 * promote it to be processed to be added to our @modules linked list. These 131 * failures can happen if we had a check in between a successful kernel_read_file_from_fd() 132 * call and right before we allocate the our private memory for the module 133 * which would be kept if the module is successfully loaded. The most common 134 * reason for this failure is when userspace is racing to load a module 135 * which it does not yet see loaded. The first module to succeed in 136 * add_unformed_module() will add a module to our &modules list and 137 * subsequent loads of modules with the same name will error out at the 138 * end of early_mod_check(). The check for module_patient_check_exists() 139 * at the end of early_mod_check() prevents duplicate allocations 140 * on layout_and_allocate() for modules already being processed. These 141 * duplicate failed modules are non-fatal, however they typically are 142 * indicative of userspace not seeing a module in userspace loaded yet and 143 * unnecessarily trying to load a module before the kernel even has a chance 144 * to begin to process prior requests. Although duplicate failures can be 145 * non-fatal, we should try to reduce vmalloc() pressure proactively, so 146 * ideally after boot this will be close to as 0 as possible. If module 147 * decompression was used we also add to this counter the cost of the 148 * initial kernel_read_file_from_fd() of the compressed module. If module 149 * decompression was not used the value represents the total allocated and 150 * freed bytes in kernel_read_file_from_fd() calls for these type of 151 * failures. These failures can occur because: 152 * 153 * * module_sig_check() - module signature checks 154 * * elf_validity_cache_copy() - some ELF validation issue 155 * * early_mod_check(): 156 * 157 * * blacklisting 158 * * failed to rewrite section headers 159 * * version magic 160 * * live patch requirements didn't check out 161 * * the module was detected as being already present 162 * 163 * * invalid_mod_bytes: these are the total number of bytes allocated and 164 * freed due to failures after we did all the sanity checks of the module 165 * which userspace passed to us and after our first check that the module 166 * is unique. A module can still fail to load if we detect the module is 167 * loaded after we allocate space for it with layout_and_allocate(), we do 168 * this check right before processing the module as live and run its 169 * initialization routines. Note that you have a failure of this type it 170 * also means the respective kernel_read_file_from_fd() memory space was 171 * also freed and not used, and so we increment this counter with twice 172 * the size of the module. Additionally if you used module decompression 173 * the size of the compressed module is also added to this counter. 174 * 175 * * modcount: how many modules we've loaded in our kernel life time 176 * * failed_kreads: how many modules failed due to failed kernel_read_file_from_fd() 177 * * failed_decompress: how many failed module decompression attempts we've had. 178 * These really should not happen unless your compression / decompression 179 * might be broken. 180 * * failed_becoming: how many modules failed after we kernel_read_file_from_fd() 181 * it and before we allocate memory for it with layout_and_allocate(). This 182 * counter is never incremented if you manage to validate the module and 183 * call layout_and_allocate() for it. 184 * * failed_load_modules: how many modules failed once we've allocated our 185 * private space for our module using layout_and_allocate(). These failures 186 * should hopefully mostly be dealt with already. Races in theory could 187 * still exist here, but it would just mean the kernel had started processing 188 * two threads concurrently up to early_mod_check() and one thread won. 189 * These failures are good signs the kernel or userspace is doing something 190 * seriously stupid or that could be improved. We should strive to fix these, 191 * but it is perhaps not easy to fix them. A recent example are the modules 192 * requests incurred for frequency modules, a separate module request was 193 * being issued for each CPU on a system. 194 */ 195 196 atomic_long_t total_mod_size; 197 atomic_long_t total_text_size; 198 atomic_long_t invalid_kread_bytes; 199 atomic_long_t invalid_decompress_bytes; 200 static atomic_long_t invalid_becoming_bytes; 201 static atomic_long_t invalid_mod_bytes; 202 atomic_t modcount; 203 atomic_t failed_kreads; 204 atomic_t failed_decompress; 205 static atomic_t failed_becoming; 206 static atomic_t failed_load_modules; 207 mod_fail_to_str(struct mod_fail_load * mod_fail)208 static const char *mod_fail_to_str(struct mod_fail_load *mod_fail) 209 { 210 if (test_bit(FAIL_DUP_MOD_BECOMING, &mod_fail->dup_fail_mask) && 211 test_bit(FAIL_DUP_MOD_LOAD, &mod_fail->dup_fail_mask)) 212 return "Becoming & Load"; 213 if (test_bit(FAIL_DUP_MOD_BECOMING, &mod_fail->dup_fail_mask)) 214 return "Becoming"; 215 if (test_bit(FAIL_DUP_MOD_LOAD, &mod_fail->dup_fail_mask)) 216 return "Load"; 217 return "Bug-on-stats"; 218 } 219 mod_stat_bump_invalid(struct load_info * info,int flags)220 void mod_stat_bump_invalid(struct load_info *info, int flags) 221 { 222 atomic_long_add(info->len * 2, &invalid_mod_bytes); 223 atomic_inc(&failed_load_modules); 224 #if defined(CONFIG_MODULE_DECOMPRESS) 225 if (flags & MODULE_INIT_COMPRESSED_FILE) 226 atomic_long_add(info->compressed_len, &invalid_mod_bytes); 227 #endif 228 } 229 mod_stat_bump_becoming(struct load_info * info,int flags)230 void mod_stat_bump_becoming(struct load_info *info, int flags) 231 { 232 atomic_inc(&failed_becoming); 233 atomic_long_add(info->len, &invalid_becoming_bytes); 234 #if defined(CONFIG_MODULE_DECOMPRESS) 235 if (flags & MODULE_INIT_COMPRESSED_FILE) 236 atomic_long_add(info->compressed_len, &invalid_becoming_bytes); 237 #endif 238 } 239 try_add_failed_module(const char * name,enum fail_dup_mod_reason reason)240 int try_add_failed_module(const char *name, enum fail_dup_mod_reason reason) 241 { 242 struct mod_fail_load *mod_fail; 243 244 list_for_each_entry_rcu(mod_fail, &dup_failed_modules, list, 245 lockdep_is_held(&module_mutex)) { 246 if (!strcmp(mod_fail->name, name)) { 247 atomic_long_inc(&mod_fail->count); 248 __set_bit(reason, &mod_fail->dup_fail_mask); 249 goto out; 250 } 251 } 252 253 mod_fail = kzalloc(sizeof(*mod_fail), GFP_KERNEL); 254 if (!mod_fail) 255 return -ENOMEM; 256 memcpy(mod_fail->name, name, strlen(name)); 257 __set_bit(reason, &mod_fail->dup_fail_mask); 258 atomic_long_inc(&mod_fail->count); 259 list_add_rcu(&mod_fail->list, &dup_failed_modules); 260 out: 261 return 0; 262 } 263 264 /* 265 * At 64 bytes per module and assuming a 1024 bytes preamble we can fit the 266 * 112 module prints within 8k. 267 * 268 * 1024 + (64*112) = 8k 269 */ 270 #define MAX_PREAMBLE 1024 271 #define MAX_FAILED_MOD_PRINT 112 272 #define MAX_BYTES_PER_MOD 64 read_file_mod_stats(struct file * file,char __user * user_buf,size_t count,loff_t * ppos)273 static ssize_t read_file_mod_stats(struct file *file, char __user *user_buf, 274 size_t count, loff_t *ppos) 275 { 276 struct mod_fail_load *mod_fail; 277 unsigned int len, size, count_failed = 0; 278 char *buf; 279 int ret; 280 u32 live_mod_count, fkreads, fdecompress, fbecoming, floads; 281 unsigned long total_size, text_size, ikread_bytes, ibecoming_bytes, 282 idecompress_bytes, imod_bytes, total_virtual_lost; 283 284 live_mod_count = atomic_read(&modcount); 285 fkreads = atomic_read(&failed_kreads); 286 fdecompress = atomic_read(&failed_decompress); 287 fbecoming = atomic_read(&failed_becoming); 288 floads = atomic_read(&failed_load_modules); 289 290 total_size = atomic_long_read(&total_mod_size); 291 text_size = atomic_long_read(&total_text_size); 292 ikread_bytes = atomic_long_read(&invalid_kread_bytes); 293 idecompress_bytes = atomic_long_read(&invalid_decompress_bytes); 294 ibecoming_bytes = atomic_long_read(&invalid_becoming_bytes); 295 imod_bytes = atomic_long_read(&invalid_mod_bytes); 296 297 total_virtual_lost = ikread_bytes + idecompress_bytes + ibecoming_bytes + imod_bytes; 298 299 size = MAX_PREAMBLE + min((unsigned int)(floads + fbecoming), 300 (unsigned int)MAX_FAILED_MOD_PRINT) * MAX_BYTES_PER_MOD; 301 buf = kzalloc(size, GFP_KERNEL); 302 if (buf == NULL) 303 return -ENOMEM; 304 305 /* The beginning of our debug preamble */ 306 len = scnprintf(buf, size, "%25s\t%u\n", "Mods ever loaded", live_mod_count); 307 308 len += scnprintf(buf + len, size - len, "%25s\t%u\n", "Mods failed on kread", fkreads); 309 310 len += scnprintf(buf + len, size - len, "%25s\t%u\n", "Mods failed on decompress", 311 fdecompress); 312 len += scnprintf(buf + len, size - len, "%25s\t%u\n", "Mods failed on becoming", fbecoming); 313 314 len += scnprintf(buf + len, size - len, "%25s\t%u\n", "Mods failed on load", floads); 315 316 len += scnprintf(buf + len, size - len, "%25s\t%lu\n", "Total module size", total_size); 317 len += scnprintf(buf + len, size - len, "%25s\t%lu\n", "Total mod text size", text_size); 318 319 len += scnprintf(buf + len, size - len, "%25s\t%lu\n", "Failed kread bytes", ikread_bytes); 320 321 len += scnprintf(buf + len, size - len, "%25s\t%lu\n", "Failed decompress bytes", 322 idecompress_bytes); 323 324 len += scnprintf(buf + len, size - len, "%25s\t%lu\n", "Failed becoming bytes", ibecoming_bytes); 325 326 len += scnprintf(buf + len, size - len, "%25s\t%lu\n", "Failed kmod bytes", imod_bytes); 327 328 len += scnprintf(buf + len, size - len, "%25s\t%lu\n", "Virtual mem wasted bytes", total_virtual_lost); 329 330 if (live_mod_count && total_size) { 331 len += scnprintf(buf + len, size - len, "%25s\t%lu\n", "Average mod size", 332 DIV_ROUND_UP(total_size, live_mod_count)); 333 } 334 335 if (live_mod_count && text_size) { 336 len += scnprintf(buf + len, size - len, "%25s\t%lu\n", "Average mod text size", 337 DIV_ROUND_UP(text_size, live_mod_count)); 338 } 339 340 /* 341 * We use WARN_ON_ONCE() for the counters to ensure we always have parity 342 * for keeping tabs on a type of failure with one type of byte counter. 343 * The counters for imod_bytes does not increase for fkreads failures 344 * for example, and so on. 345 */ 346 347 WARN_ON_ONCE(ikread_bytes && !fkreads); 348 if (fkreads && ikread_bytes) { 349 len += scnprintf(buf + len, size - len, "%25s\t%lu\n", "Avg fail kread bytes", 350 DIV_ROUND_UP(ikread_bytes, fkreads)); 351 } 352 353 WARN_ON_ONCE(ibecoming_bytes && !fbecoming); 354 if (fbecoming && ibecoming_bytes) { 355 len += scnprintf(buf + len, size - len, "%25s\t%lu\n", "Avg fail becoming bytes", 356 DIV_ROUND_UP(ibecoming_bytes, fbecoming)); 357 } 358 359 WARN_ON_ONCE(idecompress_bytes && !fdecompress); 360 if (fdecompress && idecompress_bytes) { 361 len += scnprintf(buf + len, size - len, "%25s\t%lu\n", "Avg fail decomp bytes", 362 DIV_ROUND_UP(idecompress_bytes, fdecompress)); 363 } 364 365 WARN_ON_ONCE(imod_bytes && !floads); 366 if (floads && imod_bytes) { 367 len += scnprintf(buf + len, size - len, "%25s\t%lu\n", "Average fail load bytes", 368 DIV_ROUND_UP(imod_bytes, floads)); 369 } 370 371 /* End of our debug preamble header. */ 372 373 /* Catch when we've gone beyond our expected preamble */ 374 WARN_ON_ONCE(len >= MAX_PREAMBLE); 375 376 if (list_empty(&dup_failed_modules)) 377 goto out; 378 379 len += scnprintf(buf + len, size - len, "Duplicate failed modules:\n"); 380 len += scnprintf(buf + len, size - len, "%25s\t%15s\t%25s\n", 381 "Module-name", "How-many-times", "Reason"); 382 mutex_lock(&module_mutex); 383 384 385 list_for_each_entry_rcu(mod_fail, &dup_failed_modules, list) { 386 if (WARN_ON_ONCE(++count_failed >= MAX_FAILED_MOD_PRINT)) 387 goto out_unlock; 388 len += scnprintf(buf + len, size - len, "%25s\t%15lu\t%25s\n", mod_fail->name, 389 atomic_long_read(&mod_fail->count), mod_fail_to_str(mod_fail)); 390 } 391 out_unlock: 392 mutex_unlock(&module_mutex); 393 out: 394 ret = simple_read_from_buffer(user_buf, count, ppos, buf, len); 395 kfree(buf); 396 return ret; 397 } 398 #undef MAX_PREAMBLE 399 #undef MAX_FAILED_MOD_PRINT 400 #undef MAX_BYTES_PER_MOD 401 402 static const struct file_operations fops_mod_stats = { 403 .read = read_file_mod_stats, 404 .open = simple_open, 405 .owner = THIS_MODULE, 406 .llseek = default_llseek, 407 }; 408 409 #define mod_debug_add_ulong(name) debugfs_create_ulong(#name, 0400, mod_debugfs_root, (unsigned long *) &name.counter) 410 #define mod_debug_add_atomic(name) debugfs_create_atomic_t(#name, 0400, mod_debugfs_root, &name) module_stats_init(void)411 static int __init module_stats_init(void) 412 { 413 mod_debug_add_ulong(total_mod_size); 414 mod_debug_add_ulong(total_text_size); 415 mod_debug_add_ulong(invalid_kread_bytes); 416 mod_debug_add_ulong(invalid_decompress_bytes); 417 mod_debug_add_ulong(invalid_becoming_bytes); 418 mod_debug_add_ulong(invalid_mod_bytes); 419 420 mod_debug_add_atomic(modcount); 421 mod_debug_add_atomic(failed_kreads); 422 mod_debug_add_atomic(failed_decompress); 423 mod_debug_add_atomic(failed_becoming); 424 mod_debug_add_atomic(failed_load_modules); 425 426 debugfs_create_file("stats", 0400, mod_debugfs_root, mod_debugfs_root, &fops_mod_stats); 427 428 return 0; 429 } 430 #undef mod_debug_add_ulong 431 #undef mod_debug_add_atomic 432 module_init(module_stats_init); 433