Re: Linux 5.3-rc8

From: "Ahmed S. Darwish" <darwish.07@gmail.com>
To: "Theodore Y. Ts'o" <tytso@mit.edu>
Cc: Linus Torvalds <torvalds@linux-foundation.org>,
	Andreas Dilger <adilger.kernel@dilger.ca>,
	Jan Kara <jack@suse.cz>, Ray Strode <rstrode@redhat.com>,
	William Jon McCann <mccann@jhu.edu>,
	"Alexander E. Patrakov" <patrakov@gmail.com>,
	zhangjs <zachary@baishancloud.com>,
	linux-ext4@vger.kernel.org, lkml <linux-kernel@vger.kernel.org>
Subject: Re: Linux 5.3-rc8
Date: Sat, 14 Sep 2019 11:25:09 +0200	[thread overview]
Message-ID: <20190914092509.GA1138@darwi-home-pc> (raw)
In-Reply-To: <20190912082530.GA27365@mit.edu>

On Thu, Sep 12, 2019 at 04:25:30AM -0400, Theodore Y. Ts'o wrote:
> On Thu, Sep 12, 2019 at 05:44:21AM +0200, Ahmed S. Darwish wrote:
[...]
> 
> >     1. Cutting down the number of bits needed to initialize the CRNG
> >        to 256 bits (CHACHA20 cipher)
> 
> Does the attach patch (see below) help?
>
[...]
> 
> diff --git a/drivers/char/random.c b/drivers/char/random.c
> index 5d5ea4ce1442..b9b3a5a82abf 100644
> --- a/drivers/char/random.c
> +++ b/drivers/char/random.c
> @@ -500,7 +500,7 @@ static int crng_init = 0;
>  #define crng_ready() (likely(crng_init > 1))
>  static int crng_init_cnt = 0;
>  static unsigned long crng_global_init_time = 0;
> -#define CRNG_INIT_CNT_THRESH (2*CHACHA_KEY_SIZE)
> +#define CRNG_INIT_CNT_THRESH	CHACHA_KEY_SIZE
>  static void _extract_crng(struct crng_state *crng, __u8 out[CHACHA_BLOCK_SIZE]);
>  static void _crng_backtrack_protect(struct crng_state *crng,
>  				    __u8 tmp[CHACHA_BLOCK_SIZE], int used);

Unfortunately, it only made the early fast init faster, but didn't fix
the normal crng init blockage :-(

Here's a trace log, got by applying the patch at [1]. The boot was
continued only after typing some random keys after ~30s:

#
# entries-in-buffer/entries-written: 22/22   #P:8
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
          <idle>-0     [001] dNh.     0.687088: crng_fast_load: crng threshold = 32
          <idle>-0     [001] dNh.     0.687089: crng_fast_load: crng_init_cnt = 0
          <idle>-0     [001] dNh.     0.687090: crng_fast_load: crng_init_cnt, now set to 16
          <idle>-0     [001] dNh.     0.705208: crng_fast_load: crng threshold = 32
          <idle>-0     [001] dNh.     0.705209: crng_fast_load: crng_init_cnt = 16
          <idle>-0     [001] dNh.     0.705209: crng_fast_load: crng_init_cnt, now set to 32
          <idle>-0     [001] dNh.     0.708048: crng_fast_load: random: fast init done
             lvm-165   [001] d...     2.417971: urandom_read: random: crng_init_cnt, now set to 0
 systemd-random--179   [003] ....     2.495669: wait_for_random_bytes.part.0: wait for randomness
     dbus-daemon-274   [006] dN..     3.294331: urandom_read: random: crng_init_cnt, now set to 0
     dbus-daemon-274   [006] dN..     3.316618: urandom_read: random: crng_init_cnt, now set to 0
         polkitd-286   [007] dN..     3.873918: urandom_read: random: crng_init_cnt, now set to 0
         polkitd-286   [007] dN..     3.874303: urandom_read: random: crng_init_cnt, now set to 0
         polkitd-286   [007] dN..     3.874375: urandom_read: random: crng_init_cnt, now set to 0
         polkitd-286   [007] d...     3.886204: urandom_read: random: crng_init_cnt, now set to 0
         polkitd-286   [007] d...     3.886217: urandom_read: random: crng_init_cnt, now set to 0
         polkitd-286   [007] d...     3.888519: urandom_read: random: crng_init_cnt, now set to 0
         polkitd-286   [007] d...     3.888529: urandom_read: random: crng_init_cnt, now set to 0
 gnome-session-b-321   [006] ....     4.292034: wait_for_random_bytes.part.0: wait for randomness
          <idle>-0     [002] dNh.    36.784001: crng_reseed: random: crng init done
 gnome-session-b-321   [006] ....    36.784019: wait_for_random_bytes.part.0: wait done
 systemd-random--179   [003] ....    36.784051: wait_for_random_bytes.part.0: wait done

[1] patch:

diff --git a/drivers/char/random.c b/drivers/char/random.c
index 5d5ea4ce1442..4a50ee2c230d 100644
--- a/drivers/char/random.c
+++ b/drivers/char/random.c
@@ -500,7 +500,7 @@ static int crng_init = 0;
 #define crng_ready() (likely(crng_init > 1))
 static int crng_init_cnt = 0;
 static unsigned long crng_global_init_time = 0;
-#define CRNG_INIT_CNT_THRESH (2*CHACHA_KEY_SIZE)
+#define CRNG_INIT_CNT_THRESH (CHACHA_KEY_SIZE)
 static void _extract_crng(struct crng_state *crng, __u8 out[CHACHA_BLOCK_SIZE]);
 static void _crng_backtrack_protect(struct crng_state *crng,
 				    __u8 tmp[CHACHA_BLOCK_SIZE], int used);
@@ -931,6 +931,9 @@ static int crng_fast_load(const char *cp, size_t len)
 	unsigned long flags;
 	char *p;
 
+	trace_printk("crng threshold = %d\n", CRNG_INIT_CNT_THRESH);
+	trace_printk("crng_init_cnt = %d\n", crng_init_cnt);
+
 	if (!spin_trylock_irqsave(&primary_crng.lock, flags))
 		return 0;
 	if (crng_init != 0) {
@@ -943,11 +946,15 @@ static int crng_fast_load(const char *cp, size_t len)
 		cp++; crng_init_cnt++; len--;
 	}
 	spin_unlock_irqrestore(&primary_crng.lock, flags);
+
+	trace_printk("crng_init_cnt, now set to %d\n", crng_init_cnt);
+
 	if (crng_init_cnt >= CRNG_INIT_CNT_THRESH) {
 		invalidate_batched_entropy();
 		crng_init = 1;
 		wake_up_interruptible(&crng_init_wait);
 		pr_notice("random: fast init done\n");
+		trace_printk("random: fast init done\n");
 	}
 	return 1;
 }
@@ -1033,6 +1040,7 @@ static void crng_reseed(struct crng_state *crng, struct entropy_store *r)
 		process_random_ready_list();
 		wake_up_interruptible(&crng_init_wait);
 		pr_notice("random: crng init done\n");
+		trace_printk("random: crng init done\n");
 		if (unseeded_warning.missed) {
 			pr_notice("random: %d get_random_xx warning(s) missed "
 				  "due to ratelimiting\n",
@@ -1743,9 +1751,16 @@ EXPORT_SYMBOL(get_random_bytes);
  */
 int wait_for_random_bytes(void)
 {
+	int ret;
+
 	if (likely(crng_ready()))
 		return 0;
-	return wait_event_interruptible(crng_init_wait, crng_ready());
+
+	trace_printk("wait for randomness\n");
+	ret = wait_event_interruptible(crng_init_wait, crng_ready());
+	trace_printk("wait done\n");
+
+	return ret;
 }
 EXPORT_SYMBOL(wait_for_random_bytes);
 
@@ -1974,6 +1989,8 @@ urandom_read(struct file *file, char __user *buf, size_t nbytes, loff_t *ppos)
 			       current->comm, nbytes);
 		spin_lock_irqsave(&primary_crng.lock, flags);
 		crng_init_cnt = 0;
+		trace_printk("random: crng_init_cnt, now set to %d\n",
+			     crng_init_cnt);
 		spin_unlock_irqrestore(&primary_crng.lock, flags);
 	}
 	nbytes = min_t(size_t, nbytes, INT_MAX >> (ENTROPY_SHIFT + 3));

thanks,

-- 
darwi
http://darwish.chasingpointers.com
