xmn - max java heap size

Java más lento con un gran montón, sin exceso de gc-ing (1)

El acceso a la memoria cuesta tiempo de CPU. Acceder a más memoria no solo cuesta linealmente más tiempo de CPU, es probable que aumente la presión de la memoria caché y, por lo tanto, falle en las tasas, lo que le costará mucho más tiempo de CPU.

Ejecute su programa con perf stat java -jar ... para ver el número de errores de caché. ver el tutorial de Perf

Fuente de la imagen: "Rendimiento de sistemas: Enterprise and the Cloud Paperback", Brendan Gregg, ISBN: 978-0133390094

Dado que el tamaño de almacenamiento dinámico inicial también afecta el tamaño del espacio eden y un espacio de eden más pequeño activa un GC, esto puede conducir a un almacenamiento más compacto, que puede ser más compatible con caché (no hay objetos de puesta en marcha temporales en el montón).

Para reducir el número de diferencias entre ambas ejecuciones, intente establecer el tamaño de generación joven inicial y máximo en el mismo valor para ambas ejecuciones, de modo que solo difiera el tamaño de la generación anterior. Eso debería, probablemente, conducir a la misma actuación.

Como comentario adicional: también podría intentar iniciar la JVM con páginas enormes, podría (¡necesita medir!) Obtener un rendimiento% adicional reduciendo aún más las fallas de TLB.

Nota para futuros lectores: Restringir el nuevo tamaño de gen no necesariamente hace que su JVM sea más rápida, solo desencadena un GC que hace que la carga de trabajo de @Peng sea más rápida.
La activación manual de un GC después del arranque habría tenido el mismo efecto.

Pregunta original

Estoy ejecutando un programa Java, digamos program.jar, con un montón inicial "pequeño" (1 gb) y un montón inicial "grande" (16 gb). Cuando lo ejecuto con el pequeño montón inicial, es decir,

java -jar -Xms1g -Xmx16g program.jar

el programa termina en 12 segundos (promediado en varias ejecuciones). Por el contrario, cuando lo ejecuto con el gran montón inicial, es decir,

java -jar -Xms16g -Xmx16g program.jar

el programa termina en 30 segundos (promediado en varias ejecuciones).

Entiendo por otras preguntas en SO que, en general, grandes montones pueden dar lugar a una excesiva recolección de basura, lo que ralentiza el programa:

Sin embargo, cuando ejecuto program.jar con flag -verbose:gc , no se informa ninguna actividad de gc con el montón inicial grande. Con el pequeño montón inicial, solo hay algo de actividad de gc durante una fase de inicialización del programa, antes de comenzar a medir el tiempo. Por lo tanto, la recolección excesiva de basura no parece aclarar mis observaciones.

Para hacerlo más confuso (al menos para mí), tengo un programa funcionalmente equivalente, digamos program2.jar, que tiene el mismo comportamiento de entrada-salida que program.jar. La principal diferencia es que program2.jar usa estructuras de datos menos eficientes que program.jar, al menos en términos de memoria (si program2.jar es también menos eficiente en términos de tiempo, realmente es lo que estoy tratando de determinar). Pero independientemente de si ejecuto program2.jar con el pequeño montón inicial o el gran montón inicial, siempre termina en unos 22 segundos (incluidos unos 2-3 segundos de gc-ing).

Por lo tanto, esta es mi pregunta: (¿cómo) pueden los grandes paquetes ralentizar los programas, el exceso de gc-ing a un lado?

(Esta pregunta puede parecer similar a la pregunta de Georg en " Java más lento con gran montón ", pero su problema resultó no estar relacionado con el montón. En mi caso, creo que debe tener algo que ver con el montón, ya que es el único diferencia entre las dos ejecuciones de program.jar)

Aquí hay algunos detalles que pueden ser relevantes. Estoy usando Java 7, OpenJDK:

> java -version java version "1.7.0_75" OpenJDK Runtime Environment (rhel-2.5.4.0.el6_6-x86_64 u75-b13) OpenJDK 64-Bit Server VM (build 24.75-b04, mixed mode)

Mi máquina tiene dos procesadores E5-2690V3 ( http://ark.intel.com/products/81713 ) en dos tomas (Hyper-Threading y Turbo Boost desactivadas) y tiene una memoria amplia (64 gb), de las cuales aproximadamente la mitad es gratuita. antes de ejecutar el programa:

> free total used free shared buffers cached Mem: 65588960 31751316 33837644 20 154616 23995164 -/+ buffers/cache: 7601536 57987424 Swap: 1023996 11484 1012512

Finalmente, el programa tiene múltiples hilos (alrededor de 70).

Editar 1

En respuesta a Bruno Reis y kdgregory

Recopilé alguna estadística adicional. Esto es para program.jar con un pequeño montón inicial:

Command being timed: "java -Xms1g -Xmx16g -verbose:gc -jar program.jar" User time (seconds): 339.11 System time (seconds): 29.86 Percent of CPU this job got: 701% Elapsed (wall clock) time (h:mm:ss or m:ss): 0:52.61 Average shared text size (kbytes): 0 Average unshared data size (kbytes): 0 Average stack size (kbytes): 0 Average total size (kbytes): 0 Maximum resident set size (kbytes): 12192224 Average resident set size (kbytes): 0 Major (requiring I/O) page faults: 1 Minor (reclaiming a frame) page faults: 771372 Voluntary context switches: 7446 Involuntary context switches: 27788 Swaps: 0 File system inputs: 10216 File system outputs: 120 Socket messages sent: 0 Socket messages received: 0 Signals delivered: 0 Page size (bytes): 4096 Exit status: 0

Esto es para program.jar con un gran montón inicial:

Command being timed: "java -Xms16g -Xmx16g -verbose:gc -jar program.jar" User time (seconds): 769.13 System time (seconds): 28.04 Percent of CPU this job got: 1101% Elapsed (wall clock) time (h:mm:ss or m:ss): 1:12.34 Average shared text size (kbytes): 0 Average unshared data size (kbytes): 0 Average stack size (kbytes): 0 Average total size (kbytes): 0 Maximum resident set size (kbytes): 10974528 Average resident set size (kbytes): 0 Major (requiring I/O) page faults: 16 Minor (reclaiming a frame) page faults: 687727 Voluntary context switches: 6769 Involuntary context switches: 68465 Swaps: 0 File system inputs: 2032 File system outputs: 160 Socket messages sent: 0 Socket messages received: 0 Signals delivered: 0 Page size (bytes): 4096 Exit status: 0

(Los tiempos del reloj de pared informados aquí difieren de los reportados en mi publicación original debido a una fase de inicialización previamente no programada).

Editar 2

En respuesta a la respuesta inicial del 8472 y comentarios posteriores

Recopilé algunas estadísticas sobre cachés. Esto es para program.jar con un pequeño montón inicial (promediado sobre 30 ejecuciones):

2719852136 cache-references ( +- 1.56% ) [42.11%] 1931377514 cache-misses # 71.010 % of all cache refs ( +- 0.07% ) [42.11%] 56748034419 L1-dcache-loads ( +- 1.34% ) [42.12%] 16334611643 L1-dcache-load-misses # 28.78% of all L1-dcache hits ( +- 1.70% ) [42.12%] 24886806040 L1-dcache-stores ( +- 1.47% ) [42.12%] 2438414068 L1-dcache-store-misses ( +- 0.19% ) [42.13%] 0 L1-dcache-prefetch-misses [42.13%] 23243029 L1-icache-load-misses ( +- 0.66% ) [42.14%] 2424355365 LLC-loads ( +- 1.73% ) [42.15%] 278916135 LLC-stores ( +- 0.30% ) [42.16%] 515064030 LLC-prefetches ( +- 0.33% ) [10.54%] 63395541507 dTLB-loads ( +- 0.17% ) [15.82%] 7402222750 dTLB-load-misses # 11.68% of all dTLB cache hits ( +- 1.87% ) [21.08%] 20945323550 dTLB-stores ( +- 0.69% ) [26.34%] 294311496 dTLB-store-misses ( +- 0.16% ) [31.60%] 17012236 iTLB-loads ( +- 2.10% ) [36.86%] 473238 iTLB-load-misses # 2.78% of all iTLB cache hits ( +- 2.88% ) [42.12%] 29390940710 branch-loads ( +- 0.18% ) [42.11%] 19502228 branch-load-misses ( +- 0.57% ) [42.11%] 53.771209341 seconds time elapsed ( +- 0.42% )

Esto es para program.jar con un gran montón inicial (promediado sobre 30 ejecuciones):

10465831994 cache-references ( +- 3.00% ) [42.10%] 1921281060 cache-misses # 18.358 % of all cache refs ( +- 0.03% ) [42.10%] 51072650956 L1-dcache-loads ( +- 2.14% ) [42.10%] 24282459597 L1-dcache-load-misses # 47.54% of all L1-dcache hits ( +- 0.16% ) [42.10%] 21447495598 L1-dcache-stores ( +- 2.46% ) [42.10%] 2441970496 L1-dcache-store-misses ( +- 0.13% ) [42.10%] 0 L1-dcache-prefetch-misses [42.11%] 24953833 L1-icache-load-misses ( +- 0.78% ) [42.12%] 10234572163 LLC-loads ( +- 3.09% ) [42.13%] 240843257 LLC-stores ( +- 0.17% ) [42.14%] 462484975 LLC-prefetches ( +- 0.22% ) [10.53%] 62564723493 dTLB-loads ( +- 0.10% ) [15.80%] 12686305321 dTLB-load-misses # 20.28% of all dTLB cache hits ( +- 0.01% ) [21.06%] 19201170089 dTLB-stores ( +- 1.11% ) [26.33%] 279236455 dTLB-store-misses ( +- 0.10% ) [31.59%] 16259758 iTLB-loads ( +- 4.65% ) [36.85%] 466127 iTLB-load-misses # 2.87% of all iTLB cache hits ( +- 6.68% ) [42.11%] 28098428012 branch-loads ( +- 0.13% ) [42.10%] 18707911 branch-load-misses ( +- 0.82% ) [42.10%] 73.576058909 seconds time elapsed ( +- 0.54% )

Comparando los números absolutos, el gran montón inicial da como resultado aproximadamente un 50% más de pérdida de carga de caché de L1 y un 70% más de carga de falta de DTLB. Hice un cálculo inverso para dTLB-load-misses, suponiendo 100 cycle / miss (fuente: Wikipedia ) en mi máquina de 2,6 ghz, lo que da un retraso de 484 segundos para el gran montón inicial frente a un 284 segundo demora con el pequeño. No sé cómo volver a traducir este número en un retraso por núcleo (probablemente no solo dividir por el número de núcleos), pero el orden de magnitud parece plausible.

Después de recopilar estas estadísticas, también di-ed el resultado de -XX:+PrintFlagsFinal para el montón inicial grande y pequeño (basado en una ejecución para cada uno de estos dos casos):

< uintx InitialHeapSize := 17179869184 {product} --- > uintx InitialHeapSize := 1073741824 {product}

Entonces, ninguna otra bandera parece afectada por -Xms . Aquí también está la salida de -XX:+PrintGCDetails para program.jar con un pequeño montón inicial:

[GC [PSYoungGen: 239882K->33488K(306176K)] 764170K->983760K(1271808K), 0.0840630 secs] [Times: user=0.70 sys=0.66, real=0.09 secs] [Full GC [PSYoungGen: 33488K->0K(306176K)] [ParOldGen: 950272K->753959K(1508352K)] 983760K->753959K(1814528K) [PSPermGen: 2994K->2993K(21504K)], 0.0560900 secs] [Times: user=0.20 sys=0.03, real=0.05 secs] [GC [PSYoungGen: 234744K->33056K(306176K)] 988704K->983623K(1814528K), 0.0416120 secs] [Times: user=0.69 sys=0.03, real=0.04 secs] [GC [PSYoungGen: 264198K->33056K(306176K)] 1214765K->1212999K(1814528K), 0.0489600 secs] [Times: user=0.61 sys=0.23, real=0.05 secs] [Full GC [PSYoungGen: 33056K->0K(306176K)] [ParOldGen: 1179943K->1212700K(2118656K)] 1212999K->1212700K(2424832K) [PSPermGen: 2993K->2993K(21504K)], 0.1589640 secs] [Times: user=2.27 sys=0.10, real=0.16 secs] [GC [PSYoungGen: 230538K->33056K(431616K)] 1443238K->1442364K(2550272K), 0.0523620 secs] [Times: user=0.69 sys=0.23, real=0.05 secs] [GC [PSYoungGen: 427431K->33152K(557568K)] 1836740K->1835676K(2676224K), 0.0774750 secs] [Times: user=0.64 sys=0.72, real=0.08 secs] [Full GC [PSYoungGen: 33152K->0K(557568K)] [ParOldGen: 1802524K->1835328K(2897920K)] 1835676K->1835328K(3455488K) [PSPermGen: 2993K->2993K(21504K)], 0.2019870 secs] [Times: user=2.74 sys=0.13, real=0.20 secs] [GC [PSYoungGen: 492503K->33280K(647168K)] 2327831K->2327360K(3545088K), 0.0870810 secs] [Times: user=0.61 sys=0.92, real=0.09 secs] [Full GC [PSYoungGen: 33280K->0K(647168K)] [ParOldGen: 2294080K->2326876K(3603968K)] 2327360K->2326876K(4251136K) [PSPermGen: 2993K->2993K(21504K)], 0.0512730 secs] [Times: user=0.09 sys=0.12, real=0.05 secs] Heap PSYoungGen total 647168K, used 340719K [0x00000006aaa80000, 0x00000006dd000000, 0x0000000800000000) eden space 613376K, 55% used [0x00000006aaa80000,0x00000006bf73bc10,0x00000006d0180000) from space 33792K, 0% used [0x00000006d2280000,0x00000006d2280000,0x00000006d4380000) to space 33792K, 0% used [0x00000006d0180000,0x00000006d0180000,0x00000006d2280000) ParOldGen total 3603968K, used 2326876K [0x0000000400000000, 0x00000004dbf80000, 0x00000006aaa80000) object space 3603968K, 64% used [0x0000000400000000,0x000000048e0572d8,0x00000004dbf80000) PSPermGen total 21504K, used 3488K [0x00000003f5a00000, 0x00000003f6f00000, 0x0000000400000000) object space 21504K, 16% used [0x00000003f5a00000,0x00000003f5d68070,0x00000003f6f00000)

Y para program.jar con un gran montón inicial:

Heap PSYoungGen total 4893696K, used 2840362K [0x00000006aaa80000, 0x0000000800000000, 0x0000000800000000) eden space 4194816K, 67% used [0x00000006aaa80000,0x000000075804a920,0x00000007aab00000) from space 698880K, 0% used [0x00000007d5580000,0x00000007d5580000,0x0000000800000000) to space 698880K, 0% used [0x00000007aab00000,0x00000007aab00000,0x00000007d5580000) ParOldGen total 11185152K, used 0K [0x00000003fff80000, 0x00000006aaa80000, 0x00000006aaa80000) object space 11185152K, 0% used [0x00000003fff80000,0x00000003fff80000,0x00000006aaa80000) PSPermGen total 21504K, used 3489K [0x00000003f5980000, 0x00000003f6e80000, 0x00000003fff80000) object space 21504K, 16% used [0x00000003f5980000,0x00000003f5ce8400,0x00000003f6e80000)