Re: port-xen/53267 (XEN amd64 DomU (Dom0??) NetBSD current USERMODE() fails)

[Robert Elz <kre%munnari.OZ.AU@localhost>]

The following reply was made to PR port-xen/53267; it has been noted by GNATS.

From: Robert Elz <kre%munnari.OZ.AU@localhost>
To: "Cherry G.Mathew" <cherry%zyx.in@localhost>
Cc: gnats-bugs%NetBSD.org@localhost, netbsd-bugs%netbsd.org@localhost
Subject: Re: port-xen/53267 (XEN amd64 DomU (Dom0??) NetBSD current USERMODE() fails)
Date: Fri, 11 May 2018 19:32:55 +0700

     Date:        Fri, 11 May 2018 17:06:08 +0530
     From:        "Cherry G.Mathew" <cherry%zyx.in@localhost>
     Message-ID:  <87y3gq4e6v.fsf%zyx.in@localhost>
 
   | Actually it's a bit more complicated, depending on if you're talking
   | about amd64 or i386.
 
 But of course, it would have to be ...
 
   | In any case, the Xen hypervisor trap code "emulates" CPL by frobbing the
   | appropriate CS register bitfield in the saved stackframe. 
 
 Yes, I had seen that was intended, but not how or where it was done.
 
   | Thanks for binary searching this - I really appreciate the patience it
   | took.
 
 Not so much really, it did not take long once I started.
 
   | Please find a patch that could bandaid the current problem.
 [...]
   | Please let me know how this goes.
 
 It works great, thanks.   I will do a bit more testing to verify,
 but from my diagnostics in cgdconfig I now see ...
 
 netbsd# cgdconfig -g -o /tmp/P aes-cbc 192
 pkcs5_pbkdf2_time(24, 1): 10 us (0.851 -> 0.861) (sys 0.851->0.861 us)
 pkcs5_pbkdf2_time(24, 2): 5 us (0.864 -> 0.869) (sys 0.864->0.869 us)
 pkcs5_pbkdf2_time(24, 4): 9 us (0.873 -> 0.882) (sys 0.873->0.882 us)
 pkcs5_pbkdf2_time(24, 8): 18 us (0.885 -> 0.903) (sys 0.885->0.903 us)
 pkcs5_pbkdf2_time(24, 16): 33 us (0.906 -> 0.939) (sys 0.906->0.939 us)
 pkcs5_pbkdf2_time(24, 32): 65 us (0.942 -> 0.1007) (sys 0.942->0.1007 us)
 pkcs5_pbkdf2_time(24, 64): 129 us (0.1010 -> 0.1139) (sys 0.1010->0.1139 us)
 pkcs5_pbkdf2_time(24, 128): 255 us (0.1142 -> 0.1397) (sys 0.1142->0.1397 us)
 pkcs5_pbkdf2_time(24, 256): 514 us (0.1400 -> 0.1914) (sys 0.1400->0.1914 us)
 pkcs5_pbkdf2_time(24, 512): 1015 us (0.1918 -> 0.2933) (sys 0.1918->0.2933 us)
 pkcs5_pbkdf2_time(24, 1024): 4062 us (0.2937 -> 0.6999) (sys 0.2937->0.2937 us)
 pkcs5_pbkdf2_time(24, 2048): 8119 us (0.7005 -> 0.15124) (sys 0.2937->0.2937 us)
 pkcs5_pbkdf2_time(24, 4096): 16222 us (0.15130 -> 0.31352) (sys 0.2937->0.2937 us)
 pkcs5_pbkdf2_time(24, 8192): 32557 us (0.31359 -> 0.63916) (sys 0.2937->0.2937 us)
 pkcs5_pbkdf2_time(24, 503240): 1994147 us (0.63922 -> 2.58069) (sys 0.2937->0.2937 us)
 
 (the formatting there is horrid, the N.M times are N seconds and M 
 microseconds, not a decimal number at all, and the "us" right at the
 end was simply a cut/pasto (or something) - it does not belong ... but
 the actual numbers are correct, which is what matters.)
 
 The message indicates the workload (params to pkcs5_pbkdf2_time()) with how
 long that work took in microseconds (it all stops when that number gets big
 enough).   After that are the values from getrusage, before & after the work, 
 for user time (first () section) and system time (second).
 
 You can see there that up to the "512" line, user and sys times are the same,
 that means that a clock tick had not happened yet, and calcru() was using its
 fallback when it has not info to guide it, of simply dividing total consumed 
 time in half, and allocating user and sys times equally.
 
 The first tick clearly happened  here during the work for the "1024" line, and
 here allocated that tick to user mode, as the user mode time increases and
 system time does not.
 
 What it looked like before was more like ...
 
 netbsd# cgdconfig -g -o /tmp/P aes-cbc 192
 pkcs5_pbkdf2_time(24, 1): 10 us (0.860 -> 0.870) (sys 0.860->0.870 us)
 pkcs5_pbkdf2_time(24, 2): 5 us (0.874 -> 0.879) (sys 0.874->0.879 us)
 pkcs5_pbkdf2_time(24, 4): 10 us (0.882 -> 0.892) (sys 0.882->0.892 us)
 pkcs5_pbkdf2_time(24, 8): 17 us (0.896 -> 0.913) (sys 0.896->0.913 us)
 pkcs5_pbkdf2_time(24, 16): 35 us (0.916 -> 0.951) (sys 0.916->0.951 us)
 pkcs5_pbkdf2_time(24, 32): 66 us (0.954 -> 0.1020) (sys 0.954->0.1020 us)
 pkcs5_pbkdf2_time(24, 64): 130 us (0.1023 -> 0.1153) (sys 0.1023->0.1153 us)
 pkcs5_pbkdf2_time(24, 128): 259 us (0.1157 -> 0.1416) (sys 0.1157->0.1416 us)
 pkcs5_pbkdf2_time(24, 256): 517 us (0.1419 -> 0.1936) (sys 0.1419->0.1936 us)
 pkcs5_pbkdf2_time(24, 512): 1031 us (0.1939 -> 0.2970) (sys 0.1939->0.2970 us)
 pkcs5_pbkdf2_time(24, 1024): 0 us (0.2973 -> 0.2973) (sys 0.2973->0.7101 us)
 pkcs5_pbkdf2_time(24, 2048): 0 us (0.2973 -> 0.2973) (sys 0.7107->0.15357 us)
 pkcs5_pbkdf2_time(24, 4096): 0 us (0.2973 -> 0.2973) (sys 0.15365->0.31850 us)
 pkcs5_pbkdf2_time(24, 8192): 0 us (0.2973 -> 0.2973) (sys 0.31856->0.64807 us)
 pkcs5_pbkdf2_time(24, 16384): 0 us (0.2973 -> 0.2973) (sys 0.64814->0.130721 us)
 pkcs5_pbkdf2_time(24, 32768): 0 us (0.2973 -> 0.2973) (sys 0.130729->0.262540 us)
 pkcs5_pbkdf2_time(24, 65536): 0 us (0.2973 -> 0.2973) (sys 0.262550->0.526155 us)
 pkcs5_pbkdf2_time(24, 131072): 0 us (0.2973 -> 0.2973) (sys 0.526164->1.53428 us)
 
 In that one (by a co-incidence) the tick also happened during the "1024" work,
 but here, the tick was attributed to system time (as were all that followed).
 (The tick could happen any time of course - I have also seen it before the work even
 starts, and all the user times were simply 0...)
 
 The only change between those two tests was your patch, otherwise they were
 identical kernels.
 
 Thanks,
 
 Please commit it!   (Or something equiv if this really is just a bandaid.)
 
 kre