Warum verwendet der erste Aufruf von scrypt() nur 1% CPU und dauert eine halbe Stunde in GCE?

Question

[Zusammenfassung & Antwort: Anscheinend ist das Problem, dass es lange dauert, den Zufallszahlengenerator zu säen. Siehe meine Antwort unten. ]

In Google Compute Engine (GCE) dauert die allererste Anforderung meiner Java Virtual Machine App an die scrypt Kennwort Hashing-Funktion lange - weil der Code noch nicht Just-In-Time kompiliert wurde nehme ich an. Also mache ich mich warm scrypt, indem ich einen Dummy scrypt("pswd", 2,1,1) Aufruf beim Serverstart mache. Was jedoch passiert, ist, dass die CPU auf 300% + ansteigt, dort für 10-20 Sekunden bleibt und dann wieder auf 1% fällt, obwohl die Anfrage zum scrypt() noch nicht beendet ist. Jetzt bleibt die CPU für viele Minuten bei 1% (bis zu einer halben Stunde, mit 2 GCE vCPU), bis schließlich scrypt() ausgeführt wird.

Warum dieses seltsame Verhalten?

Warum scrypt() wird bei 300% CPU weiterlaufen, bis es fertig ist? Es ist nicht nicht genügend Arbeitsspeicher. Schau dir die Docker-Statistiken etwas unten an.

Nach der ersten scrypt() - Anfrage werden nachfolgende Anfragen sofort beendet. Zum Beispiel diese: SCryptUtil.scrypt("pswd", 65536, 8, 1) nimmt < 0,2 Sekunden, obwohl es viel mehr Arbeit, als dies: SCryptUtil.scrypt("pswd", 2, 1, 1) , die (wie bereits erwähnt) ist mein allererstes Scrypt() -Aufruf und dauert in der Regel ein paar Minuten mit 4 GCE vCPU - und oft etwa eine halbe Stunde, mit 2 GCE vCPU.

Ich verwende eine GCE-Instanz mit 4 vCPU, 3,6 GB RAM. Docker 1.11.1. OpenJDK 1.8.0_77. In einem Alpine Linux 3.3 Docker Container, Ubuntu 16.04 Docker Host. Kann das nicht auf meinem Laptop reproduzieren; Auf meinem Laptop ist Scrypt immer schnell, braucht kein Aufwärmen.

docker stats, nach 5-10 Sekunden: (jetzt edp_play_1, Zeile 2, verwendet 300 +% CPU)

CONTAINER   CPU %    MEM USAGE/LIMIT  MEM %    NET I/O    BLOCK I/O   PIDS 
edp_nginx_1   0.02%    55.92 MB/104.9 MB 53.33%    6.191 kB/2.897 kB 0 B/0 B   6 
edp_play_1   315.12%    914.7 MB/2.831 GB 32.31%    43.4 kB/66.09 kB 0 B/2.58 MB  67 
edp_postgres_1  0.33%    29.84 MB/314.6 MB 9.49%    529.1 kB/307.9 kB 0 B/327.7 kB  17 
edp_redis_1   0.08%    6.513 MB/52.43 MB 12.42%    4.984 kB/1.289 kB 0 B/0 B   3 

docker stats nach einer halben Minute: (jetzt edp_play_1 CPU nur 0,97% verwendet - und bleibt wie dies für bis zu einem halben Stunde, bis getan)

CONTAINER   CPU %    MEM USAGE/LIMIT  MEM %    NET I/O    BLOCK I/O   PIDS 
edp_nginx_1   0.02%    55.92 MB/104.9 MB 53.33%    6.341 kB/3.047 kB 0 B/0 B   6 
edp_play_1   0.97%    1.011 GB/2.831 GB 35.71%    130.2 kB/215.2 kB 0 B/5.546 MB  66 
edp_postgres_1  0.28%    29.84 MB/314.6 MB 9.49%    678.2 kB/394.7 kB 0 B/458.8 kB  17 
edp_redis_1   0.06%    6.513 MB/52.43 MB 12.42%    4.984 kB/1.289 kB 0 B/0 B   3 

Wenn Sie in Scala & sbt testen wollen, ist das, was für mich in GCE passiert:

scala> import com.lambdaworks.crypto.SCryptUtil 
import com.lambdaworks.crypto.SCryptUtil 

scala> def time[R](block: => R): R = { val t0 = System.nanoTime() ; val result = block ; val t1 = System.nanoTime() ; println("Elapsed time: " + (t1 - t0) + "ns") ; result ; } 
time: [R](block: => R)R 

scala> time { SCryptUtil.scrypt("dummy password 1", 2, 1, 1) } 
Elapsed time: 313823ns <-- 5 minutes 
res0: String = $s0$10101$2g6nrD0f5gDOTuP44f0mKg==$kqEe4TWSFXwtwGy3YgmIcqAhDvjMS89acST7cwPf/n4= 

scala> time { SCryptUtil.scrypt("dummy password 1", 2, 1, 1) } 
Elapsed time: 178461ns 
res1: String = $s0$10101$C0iGNvfP+ywAxDS0ARoqVw==$k60w5Jpdt28PHGKT0ypByPocCyJISrq+T1XwmPlHR5w= 

scala> time { SCryptUtil.scrypt("dummy password 1", 65536, 8, 1) } 
Elapsed time: 130900544ns <-- 0.1 seconds 
res2: String = $s0$100801$UMTfIuBRY6lO1asECmVNYg==$b8i7GABgeczVHKVssJ8c2M7Z011u0TMBtVF4VSRohKI= 

scala> 313823L/1e9 
res3: Double = 313.823

scala> 130900544L/1e9 
res4: Double = 0.130900544 

Hinweis: Dies bezieht sich nicht auf Docker. Ich habe gerade außerhalb Docker getestet, mit openjdk 8 direkt auf der GCE-Instanz installiert, und das Ergebnis ist das gleiche: scrypt(..) dauert etwa 3 Minuten das erste Mal, aber die CPU ist 90-100% im Leerlauf. Danach werden Anfragen zum scrypt sofort abgeschlossen.

Answer 1

Das Problem ist, dass es lange dauert, den Zufallszahlengenerator zu säen. Scrypt tut dies:

public static String scrypt(String passwd, int N, int r, int p) { 
    try { 
     byte[] salt = new byte[16]; 
     SecureRandom.getInstance("SHA1PRNG").nextBytes(salt); <--- look 

     byte[] derived = SCrypt.scrypt(passwd.getBytes("UTF-8"), salt, N, r, p, 32); 

(here)

Der Aufruf von nextBytes(salt) bewirkt, dass der Secure Objekt selbst säen, und das dauert bis zu einer halben Stunde, in meinem Google Compute Engine-Instanz.

Dies ist nicht auf Java oder Docker verwendet, suchen stattdessen hier: (direkt auf dem Host-Rechner, nicht in einem anderen Behälter Docker)

# < /dev/random stdbuf -o0 strings --bytes 1 | stdbuf -o0 tr -d '\n\t ' 

Dies liest zufällig Zeichen von/dev/random und ich Habe es jetzt für ein paar Minuten laufen lassen, aber nach ein paar Minuten wurden bisher nur 3 Zeichen ausgegeben. Es ist also super langsam.

Mit dem weniger zufällig, aber schneller,/dev/urandom statt, dann das:

# < /dev/urandom stdbuf -o0 strings --bytes 1 | stdbuf -o0 tr -d '\n\t ' 

druckt 99.999 Zeichen sofort.

Auf meinem Laptop, aber sofort druckt die /dev/random/ Version 30-40 Zeichen:

(https://unix.stackexchange.com/a/114883/128585 ich die oben < /dev/random ... Befehle hier). Dann blockiert es und druckt alle 10 Sekunden einen oder wenige Zeichen. Vielleicht wird es Zufall von mir, wenn ich die Maus oder die Tastatur oder das Netzwerk benutze.

---

aktualisiert

Was ich getan habe: Ich bin jetzt /dev/urandom statt mit - soweit ich im Internet gelesen habe, dass völlig in Ordnung.

Und ich begann auch einen Hardware-Zufallszahlengenerator zu verwenden; anscheinend haben die GCE-Instanzen diese.

apt install rng-tools # start using any hardware rand num gen, on Ubuntu