init_ima() adds 8 % to boot time

public inbox for linux-kernel@vger.kernel.org
 help / color / mirror / Atom feed

* init_ima() adds 8 % to boot time
@ 2022-02-19  9:44 Paul Menzel
  2022-02-20 15:19 ` Mimi Zohar
  0 siblings, 1 reply; 6+ messages in thread
From: Paul Menzel @ 2022-02-19  9:44 UTC (permalink / raw)
  To: Mimi Zohar, Dmitry Kasatkin; +Cc: linux-integrity, LKML

[-- Attachment #1: Type: text/plain, Size: 3430 bytes --]

Dear Linux folks,


Debian builds its Linux kernel image with `CONFIG_IMA=y` since version 
5.13.9 [1]. Unfortunately, on the Dell Latitude E7250 `init_ima` takes 
around 33 ms, adding 8 % to the boot time up to loading the initrd.

     [    0.000000] Linux version 5.17.0-rc4-amd64 
(debian-kernel@lists.debian.org) (gcc-11 (Debian 11.2.0-16) 11.2.0, GNU 
ld (GNU Binutils for Debian) 2.38) #1 SMP PREEMPT Debian 5.17~rc4-1~exp1 
(2022-02-18)
     […]
     [    0.238520] calling  init_tis+0x0/0xde @ 1
     [    0.254749] tpm_tis 00:08: 1.2 TPM (device-id 0x3205, rev-id 80)
     [    0.285665] initcall init_tis+0x0/0xde returned 0 after 46038 usecs
     […]
     [    0.301327] calling  init_ima+0x0/0xb5 @ 1
     [    0.301332] ima: Allocated hash algorithm: sha256
     [    0.335502] ima: No architecture policies found
     [    0.335520] initcall init_ima+0x0/0xb5 returned 0 after 33389 usecs
     […]
     [    0.447312] Run /init as init process

Tracing `init_ima` with a depth of 5 shows 
`ima_calc_boot_aggregate_tfm()` takes 24 ms, and 
`ima_add_template_entry()` takes 10 ms.

         1.282630 |   1)   swapper-1    |               | 
ima_add_boot_aggregate() {
         1.282631 |   1)   swapper-1    |               | 
ima_calc_boot_aggregate() {
         1.282631 |   1)   swapper-1    |   0.153 us    | 
ima_alloc_tfm();
         1.282631 |   1)   swapper-1    | * 24404.59 us | 
ima_calc_boot_aggregate_tfm();
         1.307037 |   1)   swapper-1    |   0.482 us    | 
ima_free_tfm.part.0();
         1.307038 |   1)   swapper-1    | * 24407.06 us |        } /* 
ima_calc_boot_aggregate */
         1.307038 |   1)   swapper-1    |               | 
ima_alloc_init_template() {
         1.307038 |   1)   swapper-1    |   0.173 us    | 
ima_template_desc_current();
         1.307039 |   1)   swapper-1    |   0.836 us    | 
__kmalloc();
         1.307040 |   1)   swapper-1    |   0.580 us    | 
__kmalloc();
         1.307041 |   1)   swapper-1    |   1.555 us    | 
ima_eventdigest_ng_init();
         1.307043 |   1)   swapper-1    |   1.275 us    | 
ima_eventname_ng_init();
         1.307044 |   1)   swapper-1    |   0.256 us    | 
ima_eventsig_init();
         1.307045 |   1)   swapper-1    |   6.618 us    |        } /* 
ima_alloc_init_template */
         1.307045 |   1)   swapper-1    |               | 
ima_store_template() {
         1.307045 |   1)   swapper-1    |   5.049 us    | 
ima_calc_field_array_hash();
         1.307051 |   1)   swapper-1    | # 9316.953 us | 
ima_add_template_entry();
         1.316369 |   1)   swapper-1    | # 9323.728 us |        } /* 
ima_store_template */
         1.316369 |   1)   swapper-1    | * 33738.54 us |      } /* 
ima_add_boot_aggregate */

Tracing `ima_calc_boot_aggregate_tfm()` (attached) shows that the first 
`tpm1_pcr_read()` takes 16 ms in `tpm_transmit()`. Is communicating with 
the TPM supposed to be that slow?

In the last years, Linux decreased it’s boot time a lot, so do you see a 
way to move things out of the hot path and get `init_ima` well below 10 
ms? (As systems get faster and faster, having systems with standard 
distributions to be up below two seconds after pressing the power button 
should be a reasonable goal (500 ms firmware (like coreboot) + 500 ms 
Linux kernel + 1 s user space).


Kind regards,

Paul


[1]: 
https://salsa.debian.org/kernel-team/linux/-/commit/6e679322d7d98d30b4a8a3d1b659c899a6e9d4df

[-- Attachment #2: linux-5.17-rc4-ima_calc_boot_aggregate_tfm.trace.txt --]
[-- Type: text/plain, Size: 21571 bytes --]

# tracer: function_graph
#
#     TIME        CPU  TASK/PID         DURATION                  FUNCTION CALLS
#      |          |     |    |           |   |                     |   |   |   |
    1.278970 |   0)   swapper-1    |               |  ima_calc_boot_aggregate_tfm() {
    1.278971 |   0)   swapper-1    |               |    tpm_pcr_read() {
    1.278971 |   0)   swapper-1    |               |      tpm_find_get_ops() {
    1.278971 |   0)   swapper-1    |               |        tpm_try_get_ops() {
    1.278971 |   0)   swapper-1    |   0.201 us    |          get_device();
    1.278972 |   0)   swapper-1    |   0.265 us    |          down_read();
    1.278972 |   0)   swapper-1    |   0.252 us    |          mutex_lock();
    1.278972 |   0)   swapper-1    |   8.257 us    |          tpm_chip_start();
    1.278981 |   0)   swapper-1    |   9.794 us    |        } /* tpm_try_get_ops */
    1.278981 |   0)   swapper-1    | + 10.120 us   |      } /* tpm_find_get_ops */
    1.278981 |   0)   swapper-1    |               |      tpm1_pcr_read() {
    1.278981 |   0)   swapper-1    |               |        __get_free_pages() {
    1.278981 |   0)   swapper-1    |   0.825 us    |          alloc_pages();
    1.278982 |   0)   swapper-1    |   1.122 us    |        } /* __get_free_pages */
    1.278983 |   0)   swapper-1    |               |        tpm_transmit_cmd() {
    1.278983 |   0)   swapper-1    |               |          tpm_transmit() {
    1.295183 |   3)   swapper-1    | * 16199.26 us |          } /* tpm_transmit */
    1.295183 |   3)   swapper-1    | * 16200.69 us |        } /* tpm_transmit_cmd */
    1.295184 |   3)   swapper-1    |               |        free_pages() {
    1.295184 |   3)   swapper-1    |   1.827 us    |          __free_pages();
    1.295186 |   3)   swapper-1    |   2.395 us    |        } /* free_pages */
    1.295186 |   3)   swapper-1    | * 16205.24 us |      } /* tpm1_pcr_read */
    1.295187 |   3)   swapper-1    |               |      tpm_put_ops() {
    1.295187 |   3)   swapper-1    |               |        tpm_chip_stop() {
    1.295187 |   3)   swapper-1    |   0.398 us    |          tpm_relinquish_locality();
    1.295188 |   3)   swapper-1    |   0.256 us    |          tpm_tis_clkrun_enable();
    1.295188 |   3)   swapper-1    |   1.426 us    |        } /* tpm_chip_stop */
    1.295189 |   3)   swapper-1    |   0.173 us    |        mutex_unlock();
    1.295189 |   3)   swapper-1    |   0.175 us    |        up_read();
    1.295189 |   3)   swapper-1    |   0.236 us    |        put_device();
    1.295190 |   3)   swapper-1    |   3.051 us    |      } /* tpm_put_ops */
    1.295190 |   3)   swapper-1    | * 16219.30 us |    } /* tpm_pcr_read */
    1.295190 |   3)   swapper-1    |               |    crypto_shash_update() {
    1.295191 |   3)   swapper-1    |   0.200 us    |      crypto_sha1_update();
    1.295191 |   3)   swapper-1    |   0.693 us    |    } /* crypto_shash_update */
    1.295191 |   3)   swapper-1    |               |    tpm_pcr_read() {
    1.295191 |   3)   swapper-1    |               |      tpm_find_get_ops() {
    1.295192 |   3)   swapper-1    |               |        tpm_try_get_ops() {
    1.295192 |   3)   swapper-1    |   0.241 us    |          get_device();
    1.295192 |   3)   swapper-1    |   0.245 us    |          down_read();
    1.295193 |   3)   swapper-1    |   0.232 us    |          mutex_lock();
    1.295193 |   3)   swapper-1    |   8.181 us    |          tpm_chip_start();
    1.295201 |   3)   swapper-1    |   9.890 us    |        } /* tpm_try_get_ops */
    1.295202 |   3)   swapper-1    | + 10.217 us   |      } /* tpm_find_get_ops */
    1.295202 |   3)   swapper-1    |               |      tpm1_pcr_read() {
    1.295202 |   3)   swapper-1    |               |        __get_free_pages() {
    1.295202 |   3)   swapper-1    |   2.108 us    |          alloc_pages();
    1.295205 |   3)   swapper-1    |   2.512 us    |        } /* __get_free_pages */
    1.295205 |   3)   swapper-1    |               |        tpm_transmit_cmd() {
    1.295205 |   3)   swapper-1    | # 1186.160 us |          tpm_transmit();
    1.296392 |   3)   swapper-1    | # 1187.552 us |        } /* tpm_transmit_cmd */
    1.296393 |   3)   swapper-1    |               |        free_pages() {
    1.296393 |   3)   swapper-1    |   1.615 us    |          __free_pages();
    1.296395 |   3)   swapper-1    |   2.090 us    |        } /* free_pages */
    1.296395 |   3)   swapper-1    | # 1193.126 us |      } /* tpm1_pcr_read */
    1.296395 |   3)   swapper-1    |               |      tpm_put_ops() {
    1.296396 |   3)   swapper-1    |               |        tpm_chip_stop() {
    1.296396 |   3)   swapper-1    |   0.394 us    |          tpm_relinquish_locality();
    1.296396 |   3)   swapper-1    |   0.249 us    |          tpm_tis_clkrun_enable();
    1.296397 |   3)   swapper-1    |   1.338 us    |        } /* tpm_chip_stop */
    1.296397 |   3)   swapper-1    |   0.168 us    |        mutex_unlock();
    1.296397 |   3)   swapper-1    |   0.163 us    |        up_read();
    1.296398 |   3)   swapper-1    |   0.241 us    |        put_device();
    1.296398 |   3)   swapper-1    |   2.996 us    |      } /* tpm_put_ops */
    1.296398 |   3)   swapper-1    | # 1207.262 us |    } /* tpm_pcr_read */
    1.296399 |   3)   swapper-1    |               |    crypto_shash_update() {
    1.296399 |   3)   swapper-1    |   0.189 us    |      crypto_sha1_update();
    1.296400 |   3)   swapper-1    |   0.919 us    |    } /* crypto_shash_update */
    1.296400 |   3)   swapper-1    |               |    tpm_pcr_read() {
    1.296400 |   3)   swapper-1    |               |      tpm_find_get_ops() {
    1.296400 |   3)   swapper-1    |               |        tpm_try_get_ops() {
    1.296401 |   3)   swapper-1    |   0.239 us    |          get_device();
    1.296401 |   3)   swapper-1    |   0.243 us    |          down_read();
    1.296402 |   3)   swapper-1    |   0.228 us    |          mutex_lock();
    1.296402 |   3)   swapper-1    |   7.939 us    |          tpm_chip_start();
    1.296410 |   3)   swapper-1    |   9.650 us    |        } /* tpm_try_get_ops */
    1.296410 |   3)   swapper-1    |   9.975 us    |      } /* tpm_find_get_ops */
    1.296411 |   3)   swapper-1    |               |      tpm1_pcr_read() {
    1.296411 |   3)   swapper-1    |               |        __get_free_pages() {
    1.296411 |   3)   swapper-1    |   2.460 us    |          alloc_pages();
    1.296414 |   3)   swapper-1    |   2.867 us    |        } /* __get_free_pages */
    1.296414 |   3)   swapper-1    |               |        tpm_transmit_cmd() {
    1.296414 |   3)   swapper-1    | # 1187.963 us |          tpm_transmit();
    1.297603 |   3)   swapper-1    | # 1189.319 us |        } /* tpm_transmit_cmd */
    1.297604 |   3)   swapper-1    |               |        free_pages() {
    1.297604 |   3)   swapper-1    |   1.612 us    |          __free_pages();
    1.297606 |   3)   swapper-1    |   2.114 us    |        } /* free_pages */
    1.297606 |   3)   swapper-1    | # 1195.291 us |      } /* tpm1_pcr_read */
    1.297606 |   3)   swapper-1    |               |      tpm_put_ops() {
    1.297606 |   3)   swapper-1    |               |        tpm_chip_stop() {
    1.297607 |   3)   swapper-1    |   0.407 us    |          tpm_relinquish_locality();
    1.297607 |   3)   swapper-1    |   0.254 us    |          tpm_tis_clkrun_enable();
    1.297608 |   3)   swapper-1    |   1.354 us    |        } /* tpm_chip_stop */
    1.297608 |   3)   swapper-1    |   0.178 us    |        mutex_unlock();
    1.297608 |   3)   swapper-1    |   0.157 us    |        up_read();
    1.297609 |   3)   swapper-1    |   0.235 us    |        put_device();
    1.297609 |   3)   swapper-1    |   2.973 us    |      } /* tpm_put_ops */
    1.297609 |   3)   swapper-1    | # 1209.350 us |    } /* tpm_pcr_read */
    1.297610 |   3)   swapper-1    |               |    crypto_shash_update() {
    1.297610 |   3)   swapper-1    |   0.186 us    |      crypto_sha1_update();
    1.297611 |   3)   swapper-1    |   0.919 us    |    } /* crypto_shash_update */
    1.297611 |   3)   swapper-1    |               |    tpm_pcr_read() {
    1.297611 |   3)   swapper-1    |               |      tpm_find_get_ops() {
    1.297612 |   3)   swapper-1    |               |        tpm_try_get_ops() {
    1.297612 |   3)   swapper-1    |   0.238 us    |          get_device();
    1.297612 |   3)   swapper-1    |   0.241 us    |          down_read();
    1.297613 |   3)   swapper-1    |   0.231 us    |          mutex_lock();
    1.297613 |   3)   swapper-1    |   7.872 us    |          tpm_chip_start();
    1.297621 |   3)   swapper-1    |   9.611 us    |        } /* tpm_try_get_ops */
    1.297621 |   3)   swapper-1    |   9.953 us    |      } /* tpm_find_get_ops */
    1.297622 |   3)   swapper-1    |               |      tpm1_pcr_read() {
    1.297622 |   3)   swapper-1    |               |        __get_free_pages() {
    1.297622 |   3)   swapper-1    |   2.088 us    |          alloc_pages();
    1.297624 |   3)   swapper-1    |   2.499 us    |        } /* __get_free_pages */
    1.297625 |   3)   swapper-1    |               |        tpm_transmit_cmd() {
    1.297625 |   3)   swapper-1    | # 1186.932 us |          tpm_transmit();
    1.298813 |   3)   swapper-1    | # 1188.266 us |        } /* tpm_transmit_cmd */
    1.298813 |   3)   swapper-1    |               |        free_pages() {
    1.298814 |   3)   swapper-1    |   1.605 us    |          __free_pages();
    1.298815 |   3)   swapper-1    |   2.086 us    |        } /* free_pages */
    1.298815 |   3)   swapper-1    | # 1193.817 us |      } /* tpm1_pcr_read */
    1.298816 |   3)   swapper-1    |               |      tpm_put_ops() {
    1.298816 |   3)   swapper-1    |               |        tpm_chip_stop() {
    1.298816 |   3)   swapper-1    |   0.415 us    |          tpm_relinquish_locality();
    1.298817 |   3)   swapper-1    |   0.264 us    |          tpm_tis_clkrun_enable();
    1.298817 |   3)   swapper-1    |   1.364 us    |        } /* tpm_chip_stop */
    1.298818 |   3)   swapper-1    |   0.170 us    |        mutex_unlock();
    1.298818 |   3)   swapper-1    |   0.157 us    |        up_read();
    1.298818 |   3)   swapper-1    |   0.264 us    |        put_device();
    1.298819 |   3)   swapper-1    |   3.007 us    |      } /* tpm_put_ops */
    1.298819 |   3)   swapper-1    | # 1207.997 us |    } /* tpm_pcr_read */
    1.298820 |   3)   swapper-1    |               |    crypto_shash_update() {
    1.298820 |   3)   swapper-1    |   0.776 us    |      crypto_sha1_update();
    1.298821 |   3)   swapper-1    |   1.564 us    |    } /* crypto_shash_update */
    1.298821 |   3)   swapper-1    |               |    tpm_pcr_read() {
    1.298821 |   3)   swapper-1    |               |      tpm_find_get_ops() {
    1.298821 |   3)   swapper-1    |               |        tpm_try_get_ops() {
    1.298822 |   3)   swapper-1    |   0.239 us    |          get_device();
    1.298822 |   3)   swapper-1    |   0.252 us    |          down_read();
    1.298823 |   3)   swapper-1    |   0.228 us    |          mutex_lock();
    1.298823 |   3)   swapper-1    |   7.872 us    |          tpm_chip_start();
    1.298831 |   3)   swapper-1    |   9.576 us    |        } /* tpm_try_get_ops */
    1.298831 |   3)   swapper-1    |   9.900 us    |      } /* tpm_find_get_ops */
    1.298831 |   3)   swapper-1    |               |      tpm1_pcr_read() {
    1.298832 |   3)   swapper-1    |               |        __get_free_pages() {
    1.298832 |   3)   swapper-1    |   2.257 us    |          alloc_pages();
    1.298834 |   3)   swapper-1    |   2.674 us    |        } /* __get_free_pages */
    1.298835 |   3)   swapper-1    |               |        tpm_transmit_cmd() {
    1.298835 |   3)   swapper-1    | # 1186.138 us |          tpm_transmit();
    1.300022 |   3)   swapper-1    | # 1187.494 us |        } /* tpm_transmit_cmd */
    1.300022 |   3)   swapper-1    |               |        free_pages() {
    1.300023 |   3)   swapper-1    |   1.619 us    |          __free_pages();
    1.300025 |   3)   swapper-1    |   2.099 us    |        } /* free_pages */
    1.300025 |   3)   swapper-1    | # 1193.254 us |      } /* tpm1_pcr_read */
    1.300025 |   3)   swapper-1    |               |      tpm_put_ops() {
    1.300025 |   3)   swapper-1    |               |        tpm_chip_stop() {
    1.300026 |   3)   swapper-1    |   0.402 us    |          tpm_relinquish_locality();
    1.300026 |   3)   swapper-1    |   0.245 us    |          tpm_tis_clkrun_enable();
    1.300027 |   3)   swapper-1    |   1.339 us    |        } /* tpm_chip_stop */
    1.300027 |   3)   swapper-1    |   0.170 us    |        mutex_unlock();
    1.300027 |   3)   swapper-1    |   0.156 us    |        up_read();
    1.300028 |   3)   swapper-1    |   0.236 us    |        put_device();
    1.300028 |   3)   swapper-1    |   2.927 us    |      } /* tpm_put_ops */
    1.300028 |   3)   swapper-1    | # 1206.993 us |    } /* tpm_pcr_read */
    1.300028 |   3)   swapper-1    |               |    crypto_shash_update() {
    1.300029 |   3)   swapper-1    |   0.191 us    |      crypto_sha1_update();
    1.300029 |   3)   swapper-1    |   0.688 us    |    } /* crypto_shash_update */
    1.300029 |   3)   swapper-1    |               |    tpm_pcr_read() {
    1.300030 |   3)   swapper-1    |               |      tpm_find_get_ops() {
    1.300030 |   3)   swapper-1    |               |        tpm_try_get_ops() {
    1.300030 |   3)   swapper-1    |   0.239 us    |          get_device();
    1.300031 |   3)   swapper-1    |   0.248 us    |          down_read();
    1.300031 |   3)   swapper-1    |   0.233 us    |          mutex_lock();
    1.300031 |   3)   swapper-1    |   8.122 us    |          tpm_chip_start();
    1.300040 |   3)   swapper-1    |   9.962 us    |        } /* tpm_try_get_ops */
    1.300040 |   3)   swapper-1    | + 10.292 us   |      } /* tpm_find_get_ops */
    1.300040 |   3)   swapper-1    |               |      tpm1_pcr_read() {
    1.300041 |   3)   swapper-1    |               |        __get_free_pages() {
    1.300041 |   3)   swapper-1    |   2.407 us    |          alloc_pages();
    1.300043 |   3)   swapper-1    |   2.813 us    |        } /* __get_free_pages */
    1.300044 |   3)   swapper-1    |               |        tpm_transmit_cmd() {
    1.300044 |   3)   swapper-1    | # 1186.643 us |          tpm_transmit();
    1.301232 |   3)   swapper-1    | # 1188.031 us |        } /* tpm_transmit_cmd */
    1.301232 |   3)   swapper-1    |               |        free_pages() {
    1.301232 |   3)   swapper-1    |   1.604 us    |          __free_pages();
    1.301234 |   3)   swapper-1    |   2.095 us    |        } /* free_pages */
    1.301234 |   3)   swapper-1    | # 1193.909 us |      } /* tpm1_pcr_read */
    1.301234 |   3)   swapper-1    |               |      tpm_put_ops() {
    1.301235 |   3)   swapper-1    |               |        tpm_chip_stop() {
    1.301235 |   3)   swapper-1    |   0.402 us    |          tpm_relinquish_locality();
    1.301236 |   3)   swapper-1    |   0.247 us    |          tpm_tis_clkrun_enable();
    1.301236 |   3)   swapper-1    |   1.622 us    |        } /* tpm_chip_stop */
    1.301237 |   3)   swapper-1    |   0.166 us    |        mutex_unlock();
    1.301237 |   3)   swapper-1    |   0.167 us    |        up_read();
    1.301237 |   3)   swapper-1    |   0.235 us    |        put_device();
    1.301238 |   3)   swapper-1    |   3.237 us    |      } /* tpm_put_ops */
    1.301238 |   3)   swapper-1    | # 1208.564 us |    } /* tpm_pcr_read */
    1.301239 |   3)   swapper-1    |               |    crypto_shash_update() {
    1.301239 |   3)   swapper-1    |   0.185 us    |      crypto_sha1_update();
    1.301239 |   3)   swapper-1    |   0.933 us    |    } /* crypto_shash_update */
    1.301239 |   3)   swapper-1    |               |    tpm_pcr_read() {
    1.301240 |   3)   swapper-1    |               |      tpm_find_get_ops() {
    1.301240 |   3)   swapper-1    |               |        tpm_try_get_ops() {
    1.301240 |   3)   swapper-1    |   0.240 us    |          get_device();
    1.301241 |   3)   swapper-1    |   0.247 us    |          down_read();
    1.301241 |   3)   swapper-1    |   0.233 us    |          mutex_lock();
    1.301242 |   3)   swapper-1    |   7.824 us    |          tpm_chip_start();
    1.301250 |   3)   swapper-1    |   9.726 us    |        } /* tpm_try_get_ops */
    1.301250 |   3)   swapper-1    | + 10.054 us   |      } /* tpm_find_get_ops */
    1.301250 |   3)   swapper-1    |               |      tpm1_pcr_read() {
    1.301250 |   3)   swapper-1    |               |        __get_free_pages() {
    1.301250 |   3)   swapper-1    |   2.341 us    |          alloc_pages();
    1.301253 |   3)   swapper-1    |   2.754 us    |        } /* __get_free_pages */
    1.301253 |   3)   swapper-1    |               |        tpm_transmit_cmd() {
    1.301253 |   3)   swapper-1    | # 1163.840 us |          tpm_transmit();
    1.302418 |   3)   swapper-1    | # 1164.639 us |        } /* tpm_transmit_cmd */
    1.302418 |   3)   swapper-1    |               |        free_pages() {
    1.302418 |   3)   swapper-1    |   0.715 us    |          __free_pages();
    1.302419 |   3)   swapper-1    |   1.154 us    |        } /* free_pages */
    1.302419 |   3)   swapper-1    | # 1169.348 us |      } /* tpm1_pcr_read */
    1.302420 |   3)   swapper-1    |               |      tpm_put_ops() {
    1.302420 |   3)   swapper-1    |               |        tpm_chip_stop() {
    1.302420 |   3)   swapper-1    |   0.331 us    |          tpm_relinquish_locality();
    1.302420 |   3)   swapper-1    |   0.185 us    |          tpm_tis_clkrun_enable();
    1.302421 |   3)   swapper-1    |   1.094 us    |        } /* tpm_chip_stop */
    1.302421 |   3)   swapper-1    |   0.180 us    |        mutex_unlock();
    1.302421 |   3)   swapper-1    |   0.159 us    |        up_read();
    1.302422 |   3)   swapper-1    |   0.177 us    |        put_device();
    1.302422 |   3)   swapper-1    |   2.493 us    |      } /* tpm_put_ops */
    1.302422 |   3)   swapper-1    | # 1182.716 us |    } /* tpm_pcr_read */
    1.302422 |   3)   swapper-1    |               |    crypto_shash_update() {
    1.302423 |   3)   swapper-1    |   0.751 us    |      crypto_sha1_update();
    1.302423 |   3)   swapper-1    |   1.103 us    |    } /* crypto_shash_update */
    1.302424 |   3)   swapper-1    |               |    tpm_pcr_read() {
    1.302424 |   3)   swapper-1    |               |      tpm_find_get_ops() {
    1.302424 |   3)   swapper-1    |               |        tpm_try_get_ops() {
    1.302424 |   3)   swapper-1    |   0.178 us    |          get_device();
    1.302425 |   3)   swapper-1    |   0.250 us    |          down_read();
    1.302425 |   3)   swapper-1    |   0.232 us    |          mutex_lock();
    1.302425 |   3)   swapper-1    |   7.807 us    |          tpm_chip_start();
    1.302433 |   3)   swapper-1    |   9.333 us    |        } /* tpm_try_get_ops */
    1.302433 |   3)   swapper-1    |   9.656 us    |      } /* tpm_find_get_ops */
    1.302434 |   3)   swapper-1    |               |      tpm1_pcr_read() {
    1.302434 |   3)   swapper-1    |               |        __get_free_pages() {
    1.302434 |   3)   swapper-1    |   1.314 us    |          alloc_pages();
    1.302436 |   3)   swapper-1    |   1.672 us    |        } /* __get_free_pages */
    1.302436 |   3)   swapper-1    |               |        tpm_transmit_cmd() {
    1.302436 |   3)   swapper-1    | # 1185.055 us |          tpm_transmit();
    1.303622 |   3)   swapper-1    | # 1186.412 us |        } /* tpm_transmit_cmd */
    1.303623 |   3)   swapper-1    |               |        free_pages() {
    1.303623 |   3)   swapper-1    |   1.623 us    |          __free_pages();
    1.303625 |   3)   swapper-1    |   2.188 us    |        } /* free_pages */
    1.303625 |   3)   swapper-1    | # 1191.170 us |      } /* tpm1_pcr_read */
    1.303625 |   3)   swapper-1    |               |      tpm_put_ops() {
    1.303625 |   3)   swapper-1    |               |        tpm_chip_stop() {
    1.303626 |   3)   swapper-1    |   0.391 us    |          tpm_relinquish_locality();
    1.303626 |   3)   swapper-1    |   0.263 us    |          tpm_tis_clkrun_enable();
    1.303627 |   3)   swapper-1    |   1.360 us    |        } /* tpm_chip_stop */
    1.303627 |   3)   swapper-1    |   0.172 us    |        mutex_unlock();
    1.303627 |   3)   swapper-1    |   0.159 us    |        up_read();
    1.303628 |   3)   swapper-1    |   0.228 us    |        put_device();
    1.303628 |   3)   swapper-1    |   2.958 us    |      } /* tpm_put_ops */
    1.303628 |   3)   swapper-1    | # 1204.582 us |    } /* tpm_pcr_read */
    1.303629 |   3)   swapper-1    |               |    crypto_shash_update() {
    1.303629 |   3)   swapper-1    |   0.183 us    |      crypto_sha1_update();
    1.303630 |   3)   swapper-1    |   0.974 us    |    } /* crypto_shash_update */
    1.303630 |   3)   swapper-1    |               |    crypto_shash_final() {
    1.303630 |   3)   swapper-1    |   0.720 us    |      sha1_final();
    1.303631 |   3)   swapper-1    |   1.155 us    |    } /* crypto_shash_final */
    1.303631 |   3)   swapper-1    | * 24661.94 us |  } /* ima_calc_boot_aggregate_tfm */

^ permalink raw reply	[flat|nested] 6+ messages in thread

* Re: init_ima() adds 8 % to boot time
  2022-02-19  9:44 init_ima() adds 8 % to boot time Paul Menzel
@ 2022-02-20 15:19 ` Mimi Zohar
  2022-02-20 22:57   ` Jarkko Sakkinen
  2022-02-22  6:25   ` Petr Vorel
  0 siblings, 2 replies; 6+ messages in thread
From: Mimi Zohar @ 2022-02-20 15:19 UTC (permalink / raw)
  To: Paul Menzel, Dmitry Kasatkin, Jarkko Sakkinen
  Cc: linux-integrity, LKML, Petr Vorel

[Cc'ing Jarkko, Petr Vorel]

Hi Paul,

On Sat, 2022-02-19 at 10:44 +0100, Paul Menzel wrote:
> Dear Linux folks,
> 
> 
> Debian builds its Linux kernel image with `CONFIG_IMA=y` since version 
> 5.13.9 [1]. Unfortunately, on the Dell Latitude E7250 `init_ima` takes 
> around 33 ms, adding 8 % to the boot time up to loading the initrd.
> 
>      [    0.000000] Linux version 5.17.0-rc4-amd64 
> (debian-kernel@lists.debian.org) (gcc-11 (Debian 11.2.0-16) 11.2.0, GNU 
> ld (GNU Binutils for Debian) 2.38) #1 SMP PREEMPT Debian 5.17~rc4-1~exp1 
> (2022-02-18)
>      […]
>      [    0.238520] calling  init_tis+0x0/0xde @ 1
>      [    0.254749] tpm_tis 00:08: 1.2 TPM (device-id 0x3205, rev-id 80)
>      [    0.285665] initcall init_tis+0x0/0xde returned 0 after 46038 usecs
>      […]
>      [    0.301327] calling  init_ima+0x0/0xb5 @ 1
>      [    0.301332] ima: Allocated hash algorithm: sha256
>      [    0.335502] ima: No architecture policies found
>      [    0.335520] initcall init_ima+0x0/0xb5 returned 0 after 33389 usecs
>      […]
>      [    0.447312] Run /init as init process
> 
> Tracing `init_ima` with a depth of 5 shows 
> `ima_calc_boot_aggregate_tfm()` takes 24 ms, and 
> `ima_add_template_entry()` takes 10 ms.
> 
>          1.282630 |   1)   swapper-1    |               | 
> ima_add_boot_aggregate() {
>          1.282631 |   1)   swapper-1    |               | 
> ima_calc_boot_agg:0regate() {
>          1.282631 |   1)   swapper-1    |   0.153 us    | 
> ima_alloc_tfm();
>          1.282631 |   1)   swapper-1    | * 24404.59 us | 
> ima_calc_boot_aggregate_tfm();
>          1.307037 |   1)   swapper-1    |   0.482 us    | 
> ima_free_tfm.part.0();
>          1.307038 |   1)   swapper-1    | * 24407.06 us |        } /* 
> ima_calc_boot_aggregate */
>          1.307038 |   1)   swapper-1    |               | 
> ima_alloc_init_template() {
>          1.307038 |   1)   swapper-1    |   0.173 us    | 
> ima_template_desc_current();
>          1.307039 |   1)   swapper-1    |   0.836 us    | 
> __kmalloc();
>          1.307040 |   1)   swapper-1    |   0.580 us    | 
> __kmalloc();
>          1.307041 |   1)   swapper-1    |   1.555 us    | 
> ima_eventdigest_ng_init();
>          1.307043 |   1)   swapper-1    |   1.275 us    | 
> ima_eventname_ng_init();
>          1.307044 |   1)   swapper-1    |   0.256 us    | 
> ima_eventsig_init();
>          1.307045 |   1)   swapper-1    |   6.618 us    |        } /* 
> ima_alloc_init_template */
>          1.307045 |   1)   swapper-1    |               | 
> ima_store_template() {
>          1.307045 |   1)   swapper-1    |   5.049 us    | 
> ima_calc_field_array_hash();
>          1.307051 |   1)   swapper-1    | # 9316.953 us | 
> ima_add_template_entry();
>          1.316369 |   1)   swapper-1    | # 9323.728 us |        } /* 
> ima_store_template */
>          1.316369 |   1)   swapper-1    | * 33738.54 us |      } /* 
> ima_add_boot_aggregate */
> 
> Tracing `ima_calc_boot_aggregate_tfm()` (attached) shows that the first 
> `tpm1_pcr_read()` takes 16 ms in `tpm_transmit()`. Is communicating with 
> the TPM supposed to be that slow?
> 
> In the last years, Linux decreased it’s boot time a lot, so do you see a 
> way to move things out of the hot path and get `init_ima` well below 10 
> ms? (As systems get faster and faster, having systems with standard 
> distributions to be up below two seconds after pressing the power button 
> should be a reasonable goal (500 ms firmware (like coreboot) + 500 ms 
> Linux kernel + 1 s user space).
> 
> 
> [1]: 
> https://salsa.debian.org/kernel-team/linux/-/commit/6e679322d7d98d30b4a8a3d1b659c899a6e9d4df

Thank you including the initial and other TPM delays.  The main reason
for the "boot_aggregate" is to tie the pre-OS measurements to the post
OS measurement list.  Without the TPM based 'boot_aggregate', any IMA
measurement list could be used to verify a TPM quote.  The
'boot_aggregate' is calculated, originally, based on PCRs 0 - 7 and
more recently may include PCRs 8 & 9 as well.  The 'boot_aggregate' is
the first record in the IMA measurement list and the first record after
a soft reboot (kexec).  It is the one and only IMA measurement record
not dependent on policy.

There are TPM 1.2 & 2.0 standards' requirements, but there are also
buggy TPMs which don't adhere to them to such an extent that IMA goes
into 'TPM-bypass' mode. Perhaps for those not interested in extending
the concepts of trusted boot to the running OS, defining a new boot
command line option to force IMA into this 'TPM-bypass' mode would be
an acceptable alternative to the delay.  The IMA measurement list would
still include a 'boot_aggregate' record, but one containing 0's.

thanks,

Mimi


^ permalink raw reply	[flat|nested] 6+ messages in thread

* Re: init_ima() adds 8 % to boot time
  2022-02-20 15:19 ` Mimi Zohar
@ 2022-02-20 22:57   ` Jarkko Sakkinen
  2022-02-20 23:19     ` Mimi Zohar
  2022-02-22  6:25   ` Petr Vorel
  1 sibling, 1 reply; 6+ messages in thread
From: Jarkko Sakkinen @ 2022-02-20 22:57 UTC (permalink / raw)
  To: Mimi Zohar
  Cc: Paul Menzel, Dmitry Kasatkin, linux-integrity, LKML, Petr Vorel

On Sun, Feb 20, 2022 at 10:19:37AM -0500, Mimi Zohar wrote:
> [Cc'ing Jarkko, Petr Vorel]
> 
> Hi Paul,
> 
> On Sat, 2022-02-19 at 10:44 +0100, Paul Menzel wrote:
> > Dear Linux folks,
> > 
> > 
> > Debian builds its Linux kernel image with `CONFIG_IMA=y` since version 
> > 5.13.9 [1]. Unfortunately, on the Dell Latitude E7250 `init_ima` takes 
> > around 33 ms, adding 8 % to the boot time up to loading the initrd.
> > 
> >      [    0.000000] Linux version 5.17.0-rc4-amd64 
> > (debian-kernel@lists.debian.org) (gcc-11 (Debian 11.2.0-16) 11.2.0, GNU 
> > ld (GNU Binutils for Debian) 2.38) #1 SMP PREEMPT Debian 5.17~rc4-1~exp1 
> > (2022-02-18)
> >      […]
> >      [    0.238520] calling  init_tis+0x0/0xde @ 1
> >      [    0.254749] tpm_tis 00:08: 1.2 TPM (device-id 0x3205, rev-id 80)
> >      [    0.285665] initcall init_tis+0x0/0xde returned 0 after 46038 usecs
> >      […]
> >      [    0.301327] calling  init_ima+0x0/0xb5 @ 1
> >      [    0.301332] ima: Allocated hash algorithm: sha256
> >      [    0.335502] ima: No architecture policies found
> >      [    0.335520] initcall init_ima+0x0/0xb5 returned 0 after 33389 usecs
> >      […]
> >      [    0.447312] Run /init as init process
> > 
> > Tracing `init_ima` with a depth of 5 shows 
> > `ima_calc_boot_aggregate_tfm()` takes 24 ms, and 
> > `ima_add_template_entry()` takes 10 ms.
> > 
> >          1.282630 |   1)   swapper-1    |               | 
> > ima_add_boot_aggregate() {
> >          1.282631 |   1)   swapper-1    |               | 
> > ima_calc_boot_agg:0regate() {
> >          1.282631 |   1)   swapper-1    |   0.153 us    | 
> > ima_alloc_tfm();
> >          1.282631 |   1)   swapper-1    | * 24404.59 us | 
> > ima_calc_boot_aggregate_tfm();
> >          1.307037 |   1)   swapper-1    |   0.482 us    | 
> > ima_free_tfm.part.0();
> >          1.307038 |   1)   swapper-1    | * 24407.06 us |        } /* 
> > ima_calc_boot_aggregate */
> >          1.307038 |   1)   swapper-1    |               | 
> > ima_alloc_init_template() {
> >          1.307038 |   1)   swapper-1    |   0.173 us    | 
> > ima_template_desc_current();
> >          1.307039 |   1)   swapper-1    |   0.836 us    | 
> > __kmalloc();
> >          1.307040 |   1)   swapper-1    |   0.580 us    | 
> > __kmalloc();
> >          1.307041 |   1)   swapper-1    |   1.555 us    | 
> > ima_eventdigest_ng_init();
> >          1.307043 |   1)   swapper-1    |   1.275 us    | 
> > ima_eventname_ng_init();
> >          1.307044 |   1)   swapper-1    |   0.256 us    | 
> > ima_eventsig_init();
> >          1.307045 |   1)   swapper-1    |   6.618 us    |        } /* 
> > ima_alloc_init_template */
> >          1.307045 |   1)   swapper-1    |               | 
> > ima_store_template() {
> >          1.307045 |   1)   swapper-1    |   5.049 us    | 
> > ima_calc_field_array_hash();
> >          1.307051 |   1)   swapper-1    | # 9316.953 us | 
> > ima_add_template_entry();
> >          1.316369 |   1)   swapper-1    | # 9323.728 us |        } /* 
> > ima_store_template */
> >          1.316369 |   1)   swapper-1    | * 33738.54 us |      } /* 
> > ima_add_boot_aggregate */
> > 
> > Tracing `ima_calc_boot_aggregate_tfm()` (attached) shows that the first 
> > `tpm1_pcr_read()` takes 16 ms in `tpm_transmit()`. Is communicating with 
> > the TPM supposed to be that slow?
> > 
> > In the last years, Linux decreased it’s boot time a lot, so do you see a 
> > way to move things out of the hot path and get `init_ima` well below 10 
> > ms? (As systems get faster and faster, having systems with standard 
> > distributions to be up below two seconds after pressing the power button 
> > should be a reasonable goal (500 ms firmware (like coreboot) + 500 ms 
> > Linux kernel + 1 s user space).
> > 
> > 
> > [1]: 
> > https://salsa.debian.org/kernel-team/linux/-/commit/6e679322d7d98d30b4a8a3d1b659c899a6e9d4df
> 
> Thank you including the initial and other TPM delays.  The main reason
> for the "boot_aggregate" is to tie the pre-OS measurements to the post
> OS measurement list.  Without the TPM based 'boot_aggregate', any IMA
> measurement list could be used to verify a TPM quote.  The
> 'boot_aggregate' is calculated, originally, based on PCRs 0 - 7 and
> more recently may include PCRs 8 & 9 as well.  The 'boot_aggregate' is
> the first record in the IMA measurement list and the first record after
> a soft reboot (kexec).  It is the one and only IMA measurement record
> not dependent on policy.
> 
> There are TPM 1.2 & 2.0 standards' requirements, but there are also
> buggy TPMs which don't adhere to them to such an extent that IMA goes
> into 'TPM-bypass' mode. Perhaps for those not interested in extending
> the concepts of trusted boot to the running OS, defining a new boot
> command line option to force IMA into this 'TPM-bypass' mode would be
> an acceptable alternative to the delay.  The IMA measurement list would
> still include a 'boot_aggregate' record, but one containing 0's.

I support the opt-in boot option.

If the full hardware specifications are known for a device, you might want
to use this.

/Jarkko

^ permalink raw reply	[flat|nested] 6+ messages in thread

* Re: init_ima() adds 8 % to boot time
  2022-02-20 22:57   ` Jarkko Sakkinen
@ 2022-02-20 23:19     ` Mimi Zohar
  2022-02-21 20:06       ` Jarkko Sakkinen
  0 siblings, 1 reply; 6+ messages in thread
From: Mimi Zohar @ 2022-02-20 23:19 UTC (permalink / raw)
  To: Jarkko Sakkinen
  Cc: Paul Menzel, Dmitry Kasatkin, linux-integrity, LKML, Petr Vorel

On Sun, 2022-02-20 at 23:57 +0100, Jarkko Sakkinen wrote:
> On Sun, Feb 20, 2022 at 10:19:37AM -0500, Mimi Zohar wrote:
> > [Cc'ing Jarkko, Petr Vorel]
> > 
> > Hi Paul,
> > 
> > On Sat, 2022-02-19 at 10:44 +0100, Paul Menzel wrote:
> > > Dear Linux folks,
> > > 
> > > 
> > > Debian builds its Linux kernel image with `CONFIG_IMA=y` since version 
> > > 5.13.9 [1]. Unfortunately, on the Dell Latitude E7250 `init_ima` takes 
> > > around 33 ms, adding 8 % to the boot time up to loading the initrd.
> > > 
> > >      [    0.000000] Linux version 5.17.0-rc4-amd64 
> > > (debian-kernel@lists.debian.org) (gcc-11 (Debian 11.2.0-16) 11.2.0, GNU 
> > > ld (GNU Binutils for Debian) 2.38) #1 SMP PREEMPT Debian 5.17~rc4-1~exp1 
> > > (2022-02-18)
> > >      […]
> > >      [    0.238520] calling  init_tis+0x0/0xde @ 1
> > >      [    0.254749] tpm_tis 00:08: 1.2 TPM (device-id 0x3205, rev-id 80)
> > >      [    0.285665] initcall init_tis+0x0/0xde returned 0 after 46038 usecs
> > >      […]
> > >      [    0.301327] calling  init_ima+0x0/0xb5 @ 1
> > >      [    0.301332] ima: Allocated hash algorithm: sha256
> > >      [    0.335502] ima: No architecture policies found
> > >      [    0.335520] initcall init_ima+0x0/0xb5 returned 0 after 33389 usecs
> > >      […]
> > >      [    0.447312] Run /init as init process
> > > 
> > > Tracing `init_ima` with a depth of 5 shows 
> > > `ima_calc_boot_aggregate_tfm()` takes 24 ms, and 
> > > `ima_add_template_entry()` takes 10 ms.
> > > 
> > >          1.282630 |   1)   swapper-1    |               | 
> > > ima_add_boot_aggregate() {
> > >          1.282631 |   1)   swapper-1    |               | 
> > > ima_calc_boot_agg:0regate() {
> > >          1.282631 |   1)   swapper-1    |   0.153 us    | 
> > > ima_alloc_tfm();
> > >          1.282631 |   1)   swapper-1    | * 24404.59 us | 
> > > ima_calc_boot_aggregate_tfm();
> > >          1.307037 |   1)   swapper-1    |   0.482 us    | 
> > > ima_free_tfm.part.0();
> > >          1.307038 |   1)   swapper-1    | * 24407.06 us |        } /* 
> > > ima_calc_boot_aggregate */
> > >          1.307038 |   1)   swapper-1    |               | 
> > > ima_alloc_init_template() {
> > >          1.307038 |   1)   swapper-1    |   0.173 us    | 
> > > ima_template_desc_current();
> > >          1.307039 |   1)   swapper-1    |   0.836 us    | 
> > > __kmalloc();
> > >          1.307040 |   1)   swapper-1    |   0.580 us    | 
> > > __kmalloc();
> > >          1.307041 |   1)   swapper-1    |   1.555 us    | 
> > > ima_eventdigest_ng_init();
> > >          1.307043 |   1)   swapper-1    |   1.275 us    | 
> > > ima_eventname_ng_init();
> > >          1.307044 |   1)   swapper-1    |   0.256 us    | 
> > > ima_eventsig_init();
> > >          1.307045 |   1)   swapper-1    |   6.618 us    |        } /* 
> > > ima_alloc_init_template */
> > >          1.307045 |   1)   swapper-1    |               | 
> > > ima_store_template() {
> > >          1.307045 |   1)   swapper-1    |   5.049 us    | 
> > > ima_calc_field_array_hash();
> > >          1.307051 |   1)   swapper-1    | # 9316.953 us | 
> > > ima_add_template_entry();
> > >          1.316369 |   1)   swapper-1    | # 9323.728 us |        } /* 
> > > ima_store_template */
> > >          1.316369 |   1)   swapper-1    | * 33738.54 us |      } /* 
> > > ima_add_boot_aggregate */
> > > 
> > > Tracing `ima_calc_boot_aggregate_tfm()` (attached) shows that the first 
> > > `tpm1_pcr_read()` takes 16 ms in `tpm_transmit()`. Is communicating with 
> > > the TPM supposed to be that slow?
> > > 
> > > In the last years, Linux decreased it’s boot time a lot, so do you see a 
> > > way to move things out of the hot path and get `init_ima` well below 10 
> > > ms? (As systems get faster and faster, having systems with standard 
> > > distributions to be up below two seconds after pressing the power button 
> > > should be a reasonable goal (500 ms firmware (like coreboot) + 500 ms 
> > > Linux kernel + 1 s user space).
> > > 
> > > 
> > > [1]: 
> > > https://salsa.debian.org/kernel-team/linux/-/commit/6e679322d7d98d30b4a8a3d1b659c899a6e9d4df
> > 
> > Thank you including the initial and other TPM delays.  The main reason
> > for the "boot_aggregate" is to tie the pre-OS measurements to the post
> > OS measurement list.  Without the TPM based 'boot_aggregate', any IMA
> > measurement list could be used to verify a TPM quote.  The
> > 'boot_aggregate' is calculated, originally, based on PCRs 0 - 7 and
> > more recently may include PCRs 8 & 9 as well.  The 'boot_aggregate' is
> > the first record in the IMA measurement list and the first record after
> > a soft reboot (kexec).  It is the one and only IMA measurement record
> > not dependent on policy.
> > 
> > There are TPM 1.2 & 2.0 standards' requirements, but there are also
> > buggy TPMs which don't adhere to them to such an extent that IMA goes
> > into 'TPM-bypass' mode. Perhaps for those not interested in extending
> > the concepts of trusted boot to the running OS, defining a new boot
> > command line option to force IMA into this 'TPM-bypass' mode would be
> > an acceptable alternative to the delay.  The IMA measurement list would
> > still include a 'boot_aggregate' record, but one containing 0's.
> 
> I support the opt-in boot option.
> 
> If the full hardware specifications are known for a device, you might want
> to use this.

The default would be to extend the TPM with the 'boot_aggregate', with
an option to opt-out of extending the TPM.

-- 
thanks,

Mimi



^ permalink raw reply	[flat|nested] 6+ messages in thread

* Re: init_ima() adds 8 % to boot time
  2022-02-20 23:19     ` Mimi Zohar
@ 2022-02-21 20:06       ` Jarkko Sakkinen
  0 siblings, 0 replies; 6+ messages in thread
From: Jarkko Sakkinen @ 2022-02-21 20:06 UTC (permalink / raw)
  To: Mimi Zohar
  Cc: Paul Menzel, Dmitry Kasatkin, linux-integrity, LKML, Petr Vorel

On Sun, Feb 20, 2022 at 06:19:59PM -0500, Mimi Zohar wrote:
> On Sun, 2022-02-20 at 23:57 +0100, Jarkko Sakkinen wrote:
> > On Sun, Feb 20, 2022 at 10:19:37AM -0500, Mimi Zohar wrote:
> > > [Cc'ing Jarkko, Petr Vorel]
> > > 
> > > Hi Paul,
> > > 
> > > On Sat, 2022-02-19 at 10:44 +0100, Paul Menzel wrote:
> > > > Dear Linux folks,
> > > > 
> > > > 
> > > > Debian builds its Linux kernel image with `CONFIG_IMA=y` since version 
> > > > 5.13.9 [1]. Unfortunately, on the Dell Latitude E7250 `init_ima` takes 
> > > > around 33 ms, adding 8 % to the boot time up to loading the initrd.
> > > > 
> > > >      [    0.000000] Linux version 5.17.0-rc4-amd64 
> > > > (debian-kernel@lists.debian.org) (gcc-11 (Debian 11.2.0-16) 11.2.0, GNU 
> > > > ld (GNU Binutils for Debian) 2.38) #1 SMP PREEMPT Debian 5.17~rc4-1~exp1 
> > > > (2022-02-18)
> > > >      […]
> > > >      [    0.238520] calling  init_tis+0x0/0xde @ 1
> > > >      [    0.254749] tpm_tis 00:08: 1.2 TPM (device-id 0x3205, rev-id 80)
> > > >      [    0.285665] initcall init_tis+0x0/0xde returned 0 after 46038 usecs
> > > >      […]
> > > >      [    0.301327] calling  init_ima+0x0/0xb5 @ 1
> > > >      [    0.301332] ima: Allocated hash algorithm: sha256
> > > >      [    0.335502] ima: No architecture policies found
> > > >      [    0.335520] initcall init_ima+0x0/0xb5 returned 0 after 33389 usecs
> > > >      […]
> > > >      [    0.447312] Run /init as init process
> > > > 
> > > > Tracing `init_ima` with a depth of 5 shows 
> > > > `ima_calc_boot_aggregate_tfm()` takes 24 ms, and 
> > > > `ima_add_template_entry()` takes 10 ms.
> > > > 
> > > >          1.282630 |   1)   swapper-1    |               | 
> > > > ima_add_boot_aggregate() {
> > > >          1.282631 |   1)   swapper-1    |               | 
> > > > ima_calc_boot_agg:0regate() {
> > > >          1.282631 |   1)   swapper-1    |   0.153 us    | 
> > > > ima_alloc_tfm();
> > > >          1.282631 |   1)   swapper-1    | * 24404.59 us | 
> > > > ima_calc_boot_aggregate_tfm();
> > > >          1.307037 |   1)   swapper-1    |   0.482 us    | 
> > > > ima_free_tfm.part.0();
> > > >          1.307038 |   1)   swapper-1    | * 24407.06 us |        } /* 
> > > > ima_calc_boot_aggregate */
> > > >          1.307038 |   1)   swapper-1    |               | 
> > > > ima_alloc_init_template() {
> > > >          1.307038 |   1)   swapper-1    |   0.173 us    | 
> > > > ima_template_desc_current();
> > > >          1.307039 |   1)   swapper-1    |   0.836 us    | 
> > > > __kmalloc();
> > > >          1.307040 |   1)   swapper-1    |   0.580 us    | 
> > > > __kmalloc();
> > > >          1.307041 |   1)   swapper-1    |   1.555 us    | 
> > > > ima_eventdigest_ng_init();
> > > >          1.307043 |   1)   swapper-1    |   1.275 us    | 
> > > > ima_eventname_ng_init();
> > > >          1.307044 |   1)   swapper-1    |   0.256 us    | 
> > > > ima_eventsig_init();
> > > >          1.307045 |   1)   swapper-1    |   6.618 us    |        } /* 
> > > > ima_alloc_init_template */
> > > >          1.307045 |   1)   swapper-1    |               | 
> > > > ima_store_template() {
> > > >          1.307045 |   1)   swapper-1    |   5.049 us    | 
> > > > ima_calc_field_array_hash();
> > > >          1.307051 |   1)   swapper-1    | # 9316.953 us | 
> > > > ima_add_template_entry();
> > > >          1.316369 |   1)   swapper-1    | # 9323.728 us |        } /* 
> > > > ima_store_template */
> > > >          1.316369 |   1)   swapper-1    | * 33738.54 us |      } /* 
> > > > ima_add_boot_aggregate */
> > > > 
> > > > Tracing `ima_calc_boot_aggregate_tfm()` (attached) shows that the first 
> > > > `tpm1_pcr_read()` takes 16 ms in `tpm_transmit()`. Is communicating with 
> > > > the TPM supposed to be that slow?
> > > > 
> > > > In the last years, Linux decreased it’s boot time a lot, so do you see a 
> > > > way to move things out of the hot path and get `init_ima` well below 10 
> > > > ms? (As systems get faster and faster, having systems with standard 
> > > > distributions to be up below two seconds after pressing the power button 
> > > > should be a reasonable goal (500 ms firmware (like coreboot) + 500 ms 
> > > > Linux kernel + 1 s user space).
> > > > 
> > > > 
> > > > [1]: 
> > > > https://salsa.debian.org/kernel-team/linux/-/commit/6e679322d7d98d30b4a8a3d1b659c899a6e9d4df
> > > 
> > > Thank you including the initial and other TPM delays.  The main reason
> > > for the "boot_aggregate" is to tie the pre-OS measurements to the post
> > > OS measurement list.  Without the TPM based 'boot_aggregate', any IMA
> > > measurement list could be used to verify a TPM quote.  The
> > > 'boot_aggregate' is calculated, originally, based on PCRs 0 - 7 and
> > > more recently may include PCRs 8 & 9 as well.  The 'boot_aggregate' is
> > > the first record in the IMA measurement list and the first record after
> > > a soft reboot (kexec).  It is the one and only IMA measurement record
> > > not dependent on policy.
> > > 
> > > There are TPM 1.2 & 2.0 standards' requirements, but there are also
> > > buggy TPMs which don't adhere to them to such an extent that IMA goes
> > > into 'TPM-bypass' mode. Perhaps for those not interested in extending
> > > the concepts of trusted boot to the running OS, defining a new boot
> > > command line option to force IMA into this 'TPM-bypass' mode would be
> > > an acceptable alternative to the delay.  The IMA measurement list would
> > > still include a 'boot_aggregate' record, but one containing 0's.
> > 
> > I support the opt-in boot option.
> > 
> > If the full hardware specifications are known for a device, you might want
> > to use this.
> 
> The default would be to extend the TPM with the 'boot_aggregate', with
> an option to opt-out of extending the TPM.

Ah, right, thanks for correction. By "opt-in" I meant "opt-out" :-)

BR, Jarkko

^ permalink raw reply	[flat|nested] 6+ messages in thread

* Re: init_ima() adds 8 % to boot time
  2022-02-20 15:19 ` Mimi Zohar
  2022-02-20 22:57   ` Jarkko Sakkinen
@ 2022-02-22  6:25   ` Petr Vorel
  1 sibling, 0 replies; 6+ messages in thread
From: Petr Vorel @ 2022-02-22  6:25 UTC (permalink / raw)
  To: Mimi Zohar
  Cc: Paul Menzel, Dmitry Kasatkin, Jarkko Sakkinen, linux-integrity,
	LKML

Hi Mimi,

> [Cc'ing Jarkko, Petr Vorel]
Thanks!

> Hi Paul,

> On Sat, 2022-02-19 at 10:44 +0100, Paul Menzel wrote:
> > Dear Linux folks,


> > Debian builds its Linux kernel image with `CONFIG_IMA=y` since version 
> > 5.13.9 [1]. Unfortunately, on the Dell Latitude E7250 `init_ima` takes 
> > around 33 ms, adding 8 % to the boot time up to loading the initrd.

> >      [    0.000000] Linux version 5.17.0-rc4-amd64 
> > (debian-kernel@lists.debian.org) (gcc-11 (Debian 11.2.0-16) 11.2.0, GNU 
> > ld (GNU Binutils for Debian) 2.38) #1 SMP PREEMPT Debian 5.17~rc4-1~exp1 
> > (2022-02-18)
> >      […]
> >      [    0.238520] calling  init_tis+0x0/0xde @ 1
> >      [    0.254749] tpm_tis 00:08: 1.2 TPM (device-id 0x3205, rev-id 80)
> >      [    0.285665] initcall init_tis+0x0/0xde returned 0 after 46038 usecs
> >      […]
> >      [    0.301327] calling  init_ima+0x0/0xb5 @ 1
> >      [    0.301332] ima: Allocated hash algorithm: sha256
> >      [    0.335502] ima: No architecture policies found
> >      [    0.335520] initcall init_ima+0x0/0xb5 returned 0 after 33389 usecs
> >      […]
> >      [    0.447312] Run /init as init process

> > Tracing `init_ima` with a depth of 5 shows 
> > `ima_calc_boot_aggregate_tfm()` takes 24 ms, and 
> > `ima_add_template_entry()` takes 10 ms.

> >          1.282630 |   1)   swapper-1    |               | 
> > ima_add_boot_aggregate() {
> >          1.282631 |   1)   swapper-1    |               | 
> > ima_calc_boot_agg:0regate() {
> >          1.282631 |   1)   swapper-1    |   0.153 us    | 
> > ima_alloc_tfm();
> >          1.282631 |   1)   swapper-1    | * 24404.59 us | 
> > ima_calc_boot_aggregate_tfm();
> >          1.307037 |   1)   swapper-1    |   0.482 us    | 
> > ima_free_tfm.part.0();
> >          1.307038 |   1)   swapper-1    | * 24407.06 us |        } /* 
> > ima_calc_boot_aggregate */
> >          1.307038 |   1)   swapper-1    |               | 
> > ima_alloc_init_template() {
> >          1.307038 |   1)   swapper-1    |   0.173 us    | 
> > ima_template_desc_current();
> >          1.307039 |   1)   swapper-1    |   0.836 us    | 
> > __kmalloc();
> >          1.307040 |   1)   swapper-1    |   0.580 us    | 
> > __kmalloc();
> >          1.307041 |   1)   swapper-1    |   1.555 us    | 
> > ima_eventdigest_ng_init();
> >          1.307043 |   1)   swapper-1    |   1.275 us    | 
> > ima_eventname_ng_init();
> >          1.307044 |   1)   swapper-1    |   0.256 us    | 
> > ima_eventsig_init();
> >          1.307045 |   1)   swapper-1    |   6.618 us    |        } /* 
> > ima_alloc_init_template */
> >          1.307045 |   1)   swapper-1    |               | 
> > ima_store_template() {
> >          1.307045 |   1)   swapper-1    |   5.049 us    | 
> > ima_calc_field_array_hash();
> >          1.307051 |   1)   swapper-1    | # 9316.953 us | 
> > ima_add_template_entry();
> >          1.316369 |   1)   swapper-1    | # 9323.728 us |        } /* 
> > ima_store_template */
> >          1.316369 |   1)   swapper-1    | * 33738.54 us |      } /* 
> > ima_add_boot_aggregate */

> > Tracing `ima_calc_boot_aggregate_tfm()` (attached) shows that the first 
> > `tpm1_pcr_read()` takes 16 ms in `tpm_transmit()`. Is communicating with 
> > the TPM supposed to be that slow?

> > In the last years, Linux decreased it’s boot time a lot, so do you see a 
> > way to move things out of the hot path and get `init_ima` well below 10 
> > ms? (As systems get faster and faster, having systems with standard 
> > distributions to be up below two seconds after pressing the power button 
> > should be a reasonable goal (500 ms firmware (like coreboot) + 500 ms 
> > Linux kernel + 1 s user space).


> > [1]: 
> > https://salsa.debian.org/kernel-team/linux/-/commit/6e679322d7d98d30b4a8a3d1b659c899a6e9d4df

> Thank you including the initial and other TPM delays.  The main reason
> for the "boot_aggregate" is to tie the pre-OS measurements to the post
> OS measurement list.  Without the TPM based 'boot_aggregate', any IMA
> measurement list could be used to verify a TPM quote.  The
> 'boot_aggregate' is calculated, originally, based on PCRs 0 - 7 and
> more recently may include PCRs 8 & 9 as well.  The 'boot_aggregate' is
> the first record in the IMA measurement list and the first record after
> a soft reboot (kexec).  It is the one and only IMA measurement record
> not dependent on policy.

> There are TPM 1.2 & 2.0 standards' requirements, but there are also
> buggy TPMs which don't adhere to them to such an extent that IMA goes
> into 'TPM-bypass' mode. Perhaps for those not interested in extending
> the concepts of trusted boot to the running OS, defining a new boot
> command line option to force IMA into this 'TPM-bypass' mode would be
> an acceptable alternative to the delay.  The IMA measurement list would
> still include a 'boot_aggregate' record, but one containing 0's.
This sounds reasonable.

Kind regards,
Petr

> thanks,

> Mimi


^ permalink raw reply	[flat|nested] 6+ messages in thread

end of thread, other threads:[~2022-02-22  6:25 UTC | newest]

Thread overview: 6+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2022-02-19  9:44 init_ima() adds 8 % to boot time Paul Menzel
2022-02-20 15:19 ` Mimi Zohar
2022-02-20 22:57   ` Jarkko Sakkinen
2022-02-20 23:19     ` Mimi Zohar
2022-02-21 20:06       ` Jarkko Sakkinen
2022-02-22  6:25   ` Petr Vorel

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox