Python problema de rendimiento de lectura lenta

Siguiendo un hilo anterior, resumí mi problema hasta convertirse en un problema, al migrar de un script de Perl a uno de Python, encontré un gran problema de rendimiento con los archivos slurping en Python. Ejecutando esto en Ubuntu Server.

NB: esto no es un hilo X vs. Y que necesito saber fundamentalmente si es así o si estoy haciendo algo estúpido.

Creé mis datos de prueba, 50,000 archivos de 10kb (esto refleja el tamaño de archivo promedio de lo que estoy procesando):

mkdir 1 cd 1 for i in {1..50000}; do dd if=/dev/zero of=$i.xml bs=1 count=10000; done cd .. cp -r 1 2 

Creé mis 2 scripts de la manera más sencilla posible:

Perl

 foreach my $file (){ my $fh; open($fh, "< $file"); my $contents = do { local $/;  }; close($fh); } 

Pitón

 import glob, sys for file in glob.iglob(sys.argv[1] + '/*.xml'): with open(file) as x: f = x.read() 

Luego borré los cachés y ejecuté mis 2 scripts slurp, entre cada ejecución limpié los cachés nuevamente usando:

 sync; sudo sh -c 'echo 3 > /proc/sys/vm/drop_caches' 

Luego se monitorea para asegurarse de que estaba leyendo todo el disco cada vez:

 sudo iotop -a -u me 

Intenté esto en una máquina física con discos RAID 10 y en una nueva configuración de VM I donde la VM está en unidades SSD RAID 1, acabo de incluir las ejecuciones de prueba de mi VM, ya que el servidor físico era mucho más rápido.

 $ time python readFiles.py 1 real 5m2.493s user 0m1.783s sys 0m5.013s $ time perl readFiles.pl 2 real 0m13.059s user 0m1.690s sys 0m2.471s $ time perl readFiles.pl 2 real 0m13.313s user 0m1.670s sys 0m2.579s $ time python readFiles.py 1 real 4m43.378s user 0m1.772s sys 0m4.731s 

Noté en iotop cuando Perl estaba ejecutando DISK READ era de alrededor de 45 M / sy IOWAIT aproximadamente 70%, cuando se ejecutaba Python DISK READ era 2M / sy IOWAIT 97%. No estoy seguro de a dónde ir después de haberlos reducido a lo más simple que puedo.

En caso de que sea relevante.

 $ python Python 2.7.6 (default, Mar 22 2014, 22:59:56) [GCC 4.8.2] on linux2 $ perl -v This is perl 5, version 18, subversion 2 (v5.18.2) built for x86_64-linux-gnu-thread-multi 

INFORMACIÓN ADICIONAL SEGÚN LO SOLICITADO

Corrí strace y agarré la información para el archivo 1000.xml pero todos parecen hacer lo mismo:

Perl

 $strace -f -T -o trace.perl.1 perl readFiles.pl 2 32303 open("2/1000.xml", O_RDONLY) = 3  32303 ioctl(3, SNDCTL_TMR_TIMEBASE or SNDRV_TIMER_IOCTL_NEXT_DEVICE or TCGETS, 0x7fff7f6f7b90) = -1 ENOTTY (Inappropriate ioctl for device)  32303 lseek(3, 0, SEEK_CUR) = 0  32303 fstat(3, {st_mode=S_IFREG|0664, st_size=10000, ...}) = 0  32303 fcntl(3, F_SETFD, FD_CLOEXEC) = 0  32303 fstat(3, {st_mode=S_IFREG|0664, st_size=10000, ...}) = 0  32303 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 8192) = 8192  32303 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 8192) = 1808  32303 read(3, "", 8192) = 0  32303 close(3) = 0  

Pitón

 $strace -f -T -o trace.python.1 python readFiles.py 1 32313 open("1/1000.xml", O_RDONLY) = 3  32313 fstat(3, {st_mode=S_IFREG|0664, st_size=10000, ...}) = 0  32313 fstat(3, {st_mode=S_IFREG|0664, st_size=10000, ...}) = 0  32313 lseek(3, 0, SEEK_CUR) = 0  32313 fstat(3, {st_mode=S_IFREG|0664, st_size=10000, ...}) = 0  32313 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fa18820a000  32313 lseek(3, 0, SEEK_CUR) = 0  32313 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 8192) = 8192  32313 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096) = 1808  32313 read(3, "", 4096) = 0  32313 close(3) = 0  32313 munmap(0x7fa18820a000, 4096) = 0  

Una diferencia que noté, no estoy seguro de si es relevante, es que parece que Perl ejecuta esto en todos los archivos antes de que empiece a abrirlos, mientras que Python no:

 32303 lstat("2/1000.xml", {st_mode=S_IFREG|0664, st_size=10000, ...}) = 0  

También ejecuté strace con -c (solo tomó algunas de las primeras llamadas):

Perl

 $ time strace -f -c perl readFiles.pl 2 % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 44.07 3.501471 23 150018 read 12.54 0.996490 10 100011 fstat 9.47 0.752552 15 50000 lstat 7.99 0.634904 13 50016 open 6.89 0.547016 11 50017 close 6.19 0.491944 10 50008 50005 ioctl 6.12 0.486208 10 50014 3 lseek 6.10 0.484374 10 50001 fcntl real 0m37.829s user 0m6.373s sys 0m25.042s 

Pitón

 $ time strace -f -c python readFiles.py 1 % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 42.97 4.186173 28 150104 read 15.58 1.518304 10 150103 fstat 10.51 1.023681 20 50242 174 open 10.12 0.986350 10 100003 lseek 7.69 0.749387 15 50047 munmap 6.85 0.667576 13 50071 close 5.90 0.574888 11 50073 mmap real 5m5.237s user 0m7.278s sys 0m30.736s 

Hicimos un análisis de la salida de strace con -T activado y contamos la primera lectura de 8192 bytes para cada archivo y está claro que aquí es donde va el tiempo, a continuación se muestra el tiempo total dedicado a las 50000 primeras lecturas de un archivo seguido de Tiempo promedio para cada lectura.

 300.247128000002 (0.00600446220302379) - Python 11.6845620000003 (0.000233681892724297) - Perl 

No estoy seguro si eso ayuda!

ACTUALIZACIÓN 2 El código actualizado en Python para usar os.open y os.read y solo hace una lectura de los primeros 4096 bytes (que funcionaría para mí ya que la información que quiero está en la parte superior del archivo), también elimina todas las demás llamadas en strace

 18346 open("1/1000.xml", O_RDONLY) = 3  18346 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096) = 4096  18346 close(3) = 0  $ time strace -f -c python readFiles.py 1 % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 55.39 2.388932 48 50104 read 22.86 0.986096 20 50242 174 open 20.72 0.893579 18 50071 close real 4m48.751s user 0m3.078s sys 0m12.360s Total Time (avg read call) 282.28626 (0.00564290374812595) 

Todavía no es mejor … ¡a continuación voy a crear una máquina virtual en Azure e intentaré allí para otro ejemplo!

ACTUALIZACIÓN 3 – ¡Disculpas por el tamaño de esto!

Bien, algunos resultados interesantes utilizando su script (@JFSebastian) en 3 configuraciones, eliminó la salida al inicio por brevedad y también eliminó todas las pruebas que simplemente se ejecutan súper rápido desde el caché y se ven así:

 0.23user 0.26system 0:00.50elapsed 99%CPU (0avgtext+0avgdata 9140maxresident)k 0inputs+0outputs (0major+2479minor)pagefaults 0swaps 

VM estándar de Azure A2 (2 cores 3.5GB RAM Disk Unknown pero lento)

 $ uname -a Linux servername 3.13.0-35-generic #62-Ubuntu SMP Fri Aug 15 01:58:42 UTC 2014 x86_64 x86_64 x86_64 GNU/Linux $ python Python 2.7.6 (default, Mar 22 2014, 22:59:56) [GCC 4.8.2] on linux2 $ perl -v This is perl 5, version 18, subversion 2 (v5.18.2) built for x86_64-linux-gnu-thread-multi (with 41 registered patches, see perl -V for more detail) + /usr/bin/time perl slurp.pl 1 1.81user 2.95system 3:11.28elapsed 2%CPU (0avgtext+0avgdata 9144maxresident)k 1233840inputs+0outputs (20major+2461minor)pagefaults 0swaps + clearcache + sync + sudo sh -c 'echo 3 > /proc/sys/vm/drop_caches' + /usr/bin/time python slurp.py 1 1.56user 3.76system 3:06.05elapsed 2%CPU (0avgtext+0avgdata 8024maxresident)k 1232232inputs+0outputs (14major+52273minor)pagefaults 0swaps + /usr/bin/time perl slurp.pl 2 1.90user 3.11system 6:02.17elapsed 1%CPU (0avgtext+0avgdata 9144maxresident)k 1233776inputs+0outputs (16major+2465minor)pagefaults 0swaps 

Resultados comparables del primer sorbo para ambos, ¿no está seguro de lo que sucedió durante el segundo sorbo de Perl?

Mi VMWare Linux VM (2 núcleos 8GB RAM Disk RAID1 SSD)

 $ uname -a Linux servername 3.13.0-32-generic #57-Ubuntu SMP Tue Jul 15 03:51:08 UTC 2014 x86_64 x86_64 x86_64 GNU/Linux $ python Python 2.7.6 (default, Mar 22 2014, 22:59:56) [GCC 4.8.2] on linux2 $ perl -v This is perl 5, version 18, subversion 2 (v5.18.2) built for x86_64-linux-gnu-thread-multi (with 41 registered patches, see perl -V for more detail) + /usr/bin/time perl slurp.pl 1 1.66user 2.55system 0:13.28elapsed 31%CPU (0avgtext+0avgdata 9136maxresident)k 1233152inputs+0outputs (20major+2460minor)pagefaults 0swaps + clearcache + sync + sudo sh -c 'echo 3 > /proc/sys/vm/drop_caches' + /usr/bin/time python slurp.py 1 2.10user 4.67system 4:45.65elapsed 2%CPU (0avgtext+0avgdata 8012maxresident)k 1232056inputs+0outputs (14major+52269minor)pagefaults 0swaps + /usr/bin/time perl slurp.pl 2 2.13user 4.11system 5:01.40elapsed 2%CPU (0avgtext+0avgdata 9140maxresident)k 1233264inputs+0outputs (16major+2463minor)pagefaults 0swaps 

Esta vez, como antes, Perl es mucho más rápido en el primer sorbo, no está seguro de lo que está sucediendo en el segundo sorbo de Perl, aunque no haya visto este comportamiento antes. Corrió measure.sh de nuevo y el resultado fue exactamente el mismo dar o demorar unos segundos. Luego hice lo que haría cualquier persona normal y actualicé el kernel para que coincida con la máquina Azure 3.13.0-35-generic y ejecuté measure.sh de nuevo y no hice ninguna diferencia en los resultados.

Por curiosidad, cambié los parámetros 1 y 2 en measure.sh y sucedió algo extraño … ¡Perl se ralentizó y Python aceleró!

 + /usr/bin/time perl slurp.pl 2 1.78user 3.46system 4:43.90elapsed 1%CPU (0avgtext+0avgdata 9140maxresident)k 1234952inputs+0outputs (21major+2458minor)pagefaults 0swaps + clearcache + sync + sudo sh -c 'echo 3 > /proc/sys/vm/drop_caches' + /usr/bin/time python slurp.py 2 1.19user 3.09system 0:10.67elapsed 40%CPU (0avgtext+0avgdata 8012maxresident)k 1233632inputs+0outputs (14major+52269minor)pagefaults 0swaps + /usr/bin/time perl slurp.pl 1 1.36user 2.32system 0:13.40elapsed 27%CPU (0avgtext+0avgdata 9136maxresident)k 1232032inputs+0outputs (17major+2465minor)pagefaults 0swaps 

Esto me acaba de confundir aún más 🙁

Servidor físico (32 núcleos 132 GB de disco RAM RAID10 SAS)

 $ uname -a Linux servername 3.5.0-23-generic #35~precise1-Ubuntu SMP Fri Jan 25 17:13:26 UTC 2013 x86_64 x86_64 x86_64 GNU/Linux $ python Python 2.7.3 (default, Aug 1 2012, 05:14:39) [GCC 4.6.3] on linux2 $ perl -v This is perl 5, version 14, subversion 2 (v5.14.2) built for x86_64-linux-gnu-thread-multi (with 55 registered patches, see perl -V for more detail) + /usr/bin/time perl slurp.pl 1 2.22user 2.60system 0:15.78elapsed 30%CPU (0avgtext+0avgdata 43728maxresident)k 1233264inputs+0outputs (15major+2984minor)pagefaults 0swaps + clearcache + sync + sudo sh -c 'echo 3 > /proc/sys/vm/drop_caches' + /usr/bin/time python slurp.py 1 2.51user 4.79system 1:58.53elapsed 6%CPU (0avgtext+0avgdata 34256maxresident)k 1234752inputs+0outputs (16major+52385minor)pagefaults 0swaps + /usr/bin/time perl slurp.pl 2 2.17user 2.95system 0:06.96elapsed 73%CPU (0avgtext+0avgdata 43744maxresident)k 1232008inputs+0outputs (14major+2987minor)pagefaults 0swaps 

Aquí Perl parece ganar todo el tiempo.

desconcertado

Dada la rareza en mi máquina virtual local, cuando intercambié directorios, que es la máquina que tengo más control, voy a probar un enfoque binario en todas las opciones posibles de ejecutar python vs perl usando 1 o 2 como el directorio de datos y Intente ejecutarlos varias veces para mantener la consistencia, pero tomará un tiempo y me estoy volviendo un poco loco, ¡por lo que es posible que se requiera un descanso primero! Todo lo que quiero es consistencia 🙁

ACTUALIZACIÓN 4 – Consistencia

(A continuación se ejecuta en una VM de ubuntu-14.04.1-server, Kernel es 3.13.0-35-generic # 62-Ubuntu)

Creo que he encontrado cierta consistencia, ejecutando las pruebas de todas las formas posibles para la inhalación de Python / Perl en el directorio de datos 1/2. Encontré lo siguiente:

  • Python siempre es lento en los archivos creados (es decir, creados por dd)
  • Python siempre es rápido en archivos copiados (es decir, creados por cp -r)
  • Perl siempre es rápido en los archivos creados (es decir, creados por dd)
  • Perl siempre es lento en los archivos copiados (es decir, creado por cp -r)

Así que miré la copia a nivel del sistema operativo y parece que en Ubuntu ‘cp’ se comporta de la misma manera que Python, es decir, lento en archivos originales y rápido en archivos copiados.

Esto es lo que ejecuté y los resultados, lo hice varias veces en una máquina con un solo SATA HD y en un sistema RAID10, resultados:

 $ mkdir 1 $ cd 1 $ for i in {1..50000}; do dd if=/dev/urandom of=$i.xml bs=1K count=10; done $ cd .. $ cp -r 1 2 $ sync; sudo sh -c 'echo 3 > /proc/sys/vm/drop_caches' $ time strace -f -c -o trace.copy2c cp -r 2 2copy real 0m28.624s user 0m1.429s sys 0m27.558s $ sync; sudo sh -c 'echo 3 > /proc/sys/vm/drop_caches' $ time strace -f -c -o trace.copy1c cp -r 1 1copy real 5m21.166s user 0m1.348s sys 0m30.717s 

Los resultados del seguimiento muestran dónde se está gastando el tiempo.

 $ head trace.copy1c trace.copy2c ==> trace.copy1c  trace.copy2c <== % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 47.86 0.802376 8 100008 read 13.55 0.227108 5 50000 write 13.02 0.218312 2 100009 open 7.36 0.123364 1 100013 close 6.83 0.114589 1 100009 fstat 6.31 0.105742 2 50004 1 lstat 3.38 0.056634 1 50000 fadvise64 1.62 0.027191 544 50 getdents 

Así que parece que copiar copias es mucho más rápido que copiar archivos originales, mi suposición actual es que cuando se copian, los archivos se alinean mejor en el disco que cuando se crearon originalmente, ¿lo que hace que sean más eficientes para leer?

Interesantemente, ‘rsyn’ y ‘cp’ funcionan de manera opuesta a la velocidad, ¡como Perl y Python!

 $ rm -rf 1copy 2copy; sync; sudo sh -c 'echo 3 > /proc/sys/vm/drop_caches'; echo "Rsync 1"; /usr/bin/time rsync -a 1 1copy; sync; sudo sh -c 'echo 3 > /proc/sys/vm/drop_caches'; echo "Rsync 2"; /usr/bin/time rsync -a 2 2copy Rsync 1 3.62user 3.76system 0:13.00elapsed 56%CPU (0avgtext+0avgdata 5072maxresident)k 1230600inputs+1200000outputs (13major+2684minor)pagefaults 0swaps Rsync 2 4.87user 6.52system 5:06.24elapsed 3%CPU (0avgtext+0avgdata 5076maxresident)k 1231832inputs+1200000outputs (13major+2689minor)pagefaults 0swaps $ rm -rf 1copy 2copy; sync; sudo sh -c 'echo 3 > /proc/sys/vm/drop_caches'; echo "Copy 1"; /usr/bin/time cp -r 1 1copy; sync; sudo sh -c 'echo 3 > /proc/sys/vm/drop_caches'; echo "Copy 2"; /usr/bin/time cp -r 2 2copy Copy 1 0.48user 6.42system 5:05.30elapsed 2%CPU (0avgtext+0avgdata 1212maxresident)k 1229432inputs+1200000outputs (6major+415minor)pagefaults 0swaps Copy 2 0.33user 4.17system 0:11.13elapsed 40%CPU (0avgtext+0avgdata 1212maxresident)k 1230416inputs+1200000outputs (6major+414minor)pagefaults 0swaps 

Me centraré solo en uno de sus ejemplos, porque las cosas en reposo deberían ser analógicas:

Lo que creo que puede importar en esta situación es la función de lectura anticipada (o quizás otra técnica relacionada con esto):

Consideremos este ejemplo:

He creado 1000 archivos xml en “1” dir (nombra 1.xml a 1000.xml) como lo hizo con el comando dd y luego copié el dirinal original 1 a dir 2

 $ mkdir 1 $ cd 1 $ for i in {1..1000}; do dd if=/dev/urandom of=$i.xml bs=1K count=10; done $ cd .. $ cp -r 1 2 $ sync; sudo sh -c 'echo 3 > /proc/sys/vm/drop_caches' $ time strace -f -c -o trace.copy2c cp -r 2 2copy $ sync; sudo sh -c 'echo 3 > /proc/sys/vm/drop_caches' $ time strace -f -c -o trace.copy1c cp -r 1 1copy 

En el siguiente paso, depuré el comando cp (por strace) para descubrir en qué orden se copian los datos:

Así que cp lo hace en el siguiente orden (solo los primeros 4 archivos, porque vi que la segunda lectura del directorio original lleva más tiempo que la segunda lectura del directorio copiado)

100.xml 150.xml 58.xml 64.xml … * en mi ejemplo

Ahora, observe los bloques del sistema de archivos que utilizan estos archivos (salida de debugfs – ext3 fs):

Directorio original:

 BLOCKS: (0-9):63038-63047 100.xml (0-9):64091-64100 150.xml (0-9):57926-57935 58.xml (0-9):60959-60968 64.xml .... Copied directory: BLOCKS: (0-9):65791-65800 100.xml (0-9):65801-65810 150.xml (0-9):65811-65820 58.xml (0-9):65821-65830 64.xml 

….

Como puede ver, en el “Directorio Copiado” el bloque es adyacente, lo que significa que durante la lectura del primer archivo 100.xml la técnica de “Lectura anticipada” (controlador o configuración del sistema) puede boost el rendimiento.

dd cree el archivo en el orden de 1.xml a 1000.xml, pero el comando cp lo copia en otro orden (100.xml, 150.xml, 58.xml, 64.xml). Entonces cuando ejecutas:

 cp -r 1 1copy 

Para copiar este directorio a otro, los bloques de archivos que se copian no son adyacentes, por lo que la lectura de dichos archivos lleva más tiempo.

Cuando copia el directorio que copió con el comando cp (por lo que los archivos no se crean con el comando dd), los archivos son adyacentes, por lo que se crea:

 cp -r 2 2copy 

La copia de la copia es más rápida.

Resumen: para probar el rendimiento de python / perl, debe usar el mismo dir (o dos dirs copiados por el comando cp) y también puede usar la opción O_DIRECT para leer sin pasar por todos los búferes del kernel y leer datos desde el disco directamente.

Recuerde que los resultados pueden ser diferentes en diferentes tipos de kernel, sistema, controlador de disco, configuración del sistema, fs, etc.

Adiciones:

  [debugfs] [root@dhcppc3 test]# debugfs /dev/sda1 debugfs 1.39 (29-May-2006) debugfs: cd test debugfs: stat test.xml Inode: 24102 Type: regular Mode: 0644 Flags: 0x0 Generation: 3385884179 User: 0 Group: 0 Size: 4 File ACL: 0 Directory ACL: 0 Links: 1 Blockcount: 2 Fragment: Address: 0 Number: 0 Size: 0 ctime: 0x543274bf -- Mon Oct 6 06:53:51 2014 atime: 0x543274be -- Mon Oct 6 06:53:50 2014 mtime: 0x543274bf -- Mon Oct 6 06:53:51 2014 BLOCKS: (0):29935 TOTAL: 1 debugfs: