python performance perl io

Problema de rendimiento de lectura lenta de Python



performance perl (1)

Me centraré solo en uno de tus ejemplos, porque el resto debe ser analógico:

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

Consideremos ese ejemplo:

He creado 1000 archivos xml en "1" dir (nombres 1.xml a 1000.xml) como lo hizo con el comando dd y luego copié el directorio original 1 en el directorio 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 orden siguiente (solo los primeros 4 archivos, porque vi que la segunda lectura del directorio original consume más tiempo que la segunda lectura del directorio copiado)

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

Ahora, eche un vistazo a los bloques del sistema de archivos que utilizan estos archivos (salida 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, por lo que significa que, durante la lectura del primer archivo 100.xml, la técnica "Leer antes de" (configuración del controlador o del sistema) puede aumentar el rendimiento.

dd crea el archivo en orden 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 leer estos archivos lleva más tiempo.

Cuando copia el directorio que ha copiado mediante el comando cp (para que los archivos no sean creados por el comando dd), el archivo se encuentra adyacente para crear:

cp -r 2 2copy

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

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

Recuerde que los resultados pueden ser diferentes en diferentes tipos de kernel, sistema, controlador de disco, configuraciones 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:

Siguiendo un hilo anterior reduje mi problema a su esencia, 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: este no es un hilo X vs. Y. 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 del archivo avg 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 simple posible:

Perl

foreach my $file (<$ARGV[0]/*.xml>){ my $fh; open($fh, "< $file"); my $contents = do { local $/; <$fh> }; 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 limpié los cachés y ejecuté mis 2 scripts de sorbos, entre cada corrida limpié los cachés nuevamente usando:

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

Luego se monitoreó para asegurarse de que estaba leyendo todo desde 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 VM que configuré donde la VM está en RAID 1 SSD, acabo de incluir las ejecuciones de prueba de mi máquina virtual 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

Me di cuenta 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 desde aquí habiéndolos reducido a lo más simple que puedo obtener.

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 SE SOLICITE

Ejecuté strace y obtuve la información para el archivo 1000.xml, pero todos parecen hacer las mismas cosas:

Perl

$strace -f -T -o trace.perl.1 perl readFiles.pl 2 32303 open("2/1000.xml", O_RDONLY) = 3 <0.000020> 32303 ioctl(3, SNDCTL_TMR_TIMEBASE or SNDRV_TIMER_IOCTL_NEXT_DEVICE or TCGETS, 0x7fff7f6f7b90) = -1 ENOTTY (Inappropriate ioctl for device) <0.000016> 32303 lseek(3, 0, SEEK_CUR) = 0 <0.000016> 32303 fstat(3, {st_mode=S_IFREG|0664, st_size=10000, ...}) = 0 <0.000016> 32303 fcntl(3, F_SETFD, FD_CLOEXEC) = 0 <0.000017> 32303 fstat(3, {st_mode=S_IFREG|0664, st_size=10000, ...}) = 0 <0.000030> 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 <0.005323> 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 <0.000022> 32303 read(3, "", 8192) = 0 <0.000019> 32303 close(3) = 0 <0.000017>

Pitón

$strace -f -T -o trace.python.1 python readFiles.py 1 32313 open("1/1000.xml", O_RDONLY) = 3 <0.000021> 32313 fstat(3, {st_mode=S_IFREG|0664, st_size=10000, ...}) = 0 <0.000017> 32313 fstat(3, {st_mode=S_IFREG|0664, st_size=10000, ...}) = 0 <0.000019> 32313 lseek(3, 0, SEEK_CUR) = 0 <0.000018> 32313 fstat(3, {st_mode=S_IFREG|0664, st_size=10000, ...}) = 0 <0.000018> 32313 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fa18820a000 <0.000019> 32313 lseek(3, 0, SEEK_CUR) = 0 <0.000018> 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 <0.006795> 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 <0.000031> 32313 read(3, "", 4096) = 0 <0.000018> 32313 close(3) = 0 <0.000027> 32313 munmap(0x7fa18820a000, 4096) = 0 <0.000022>

Una diferencia que noté, no estoy seguro si es relevante, es que Perl parece ejecutar esto contra todos los archivos antes de que comience a abrirlos mientras que python no:

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

También corrió strace con -c (solo tomó 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

¿Se ejecutó algún análisis de la salida de strace con -T y se contaron los primeros 8192 bytes de lectura 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 del tiempo promedio para cada lectura.

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

¡No estoy seguro si eso ayuda!

ACTUALIZACIÓN 2 código actualizado en Python para usar os.open y os.read y simplemente hacer una sola lectura de los primeros 4096 bytes (que me funcionaría como la información que quiero está en la parte superior del archivo), también elimina todas las otras llamadas en strace:

18346 open("1/1000.xml", O_RDONLY) = 3 <0.000026> 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 <0.007206> 18346 close(3) = 0 <0.000024> $ 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 ... ¡¡¡el siguiente voy a crear una máquina virtual en Azure y probaré allí otro ejemplo !!

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

Acepta algunos resultados interesantes usando tu script (@JFSebastian) en 3 configuraciones, quita la salida en el inicio por brevedad y también elimina todas las pruebas que acaban de ejecutarse 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

Azure A2 Standard VM (2 núcleos de 3.5 GB de RAM de disco desconocido 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

Comparables primeros resultados sorber para ambos, no estoy seguro de lo que estaba sucediendo durante la segunda sorber perl?

Mi VMWare Linux VM (2 núcleos de 8 GB de RAM de disco 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 la primera sorbida, sin estar seguro de lo que está sucediendo en el segundo sorbo de Perl, aunque nunca antes había visto este comportamiento. Vuelve a medir measure.sh y el resultado fue exactamente el mismo dar o tomar unos segundos. Luego hice lo que cualquier persona normal haría y actualicé el kernel para que coincida con la máquina de Azure 3.13.0-35-generic y ejecuté measure.sh de nuevo y no hice ninguna diferencia en los resultados.

Por curiosidad cambié el parámetro 1 y 2 en measure.sh y sucedió algo extraño ... ¡Perdió la velocidad 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 RAM de disco 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 de mi máquina virtual local, cuando intercambié directorios, que es la máquina que tengo más control, voy a intentar 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 coherencia, pero llevará un tiempo y me estoy volviendo un poco loco, ¡así que es posible que primero se requiera un descanso! Todo lo que quiero es consistencia :-(

ACTUALIZACIÓN 4 - Consistencia

(A continuación se ejecuta en una máquina virtual ubuntu-14.04.1-server, Kernel es 3.13.0-35-generic # 62-Ubuntu)

Creo que he encontrado cierta coherencia, ejecutando las pruebas de todas las formas posibles para Python / Perl sorber en el directorio de datos 1/2 Encontré lo siguiente:

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

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

Esto es lo que ejecuté y los resultados, lo hice algunas veces en una máquina con un solo SATA HD y en un sistema RAID10, los 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 <== % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 60.09 2.541250 25 100008 read 12.22 0.516799 10 50000 write 9.62 0.406904 4 100009 open 5.59 0.236274 2 100013 close 4.80 0.203114 4 50004 1 lstat 4.71 0.199211 2 100009 fstat 2.19 0.092662 2 50000 fadvise64 0.72 0.030418 608 50 getdents ==> 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

Entonces parece que copiar copias es mucho más rápido que copiar archivos originales, mi conjetura actual es que cuando se copian, los archivos se alinean en el disco mejor que cuando se crearon originalmente, haciéndolos más eficientes para leer.

Curiosamente, ''rsyn'' y ''cp'' parecen funcionar de forma opuesta a la velocidad, al igual que 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