Python 느린 읽기 성능 문제
이전 스레드를 따라 나는 내 문제를 베어 뼈로 요약했는데, Perl 스크립트에서 Python 스크립트로 마이그레이션 할 때 Python에서 파일을 슬러 핑하는 데 큰 성능 문제가 있음을 발견했습니다. Ubuntu Server에서 실행합니다.
NB : 이것은 X 대 Y 스레드가 아닙니다. 이것이 어떻게되는지 또는 내가 어리석은 일을하고 있는지 근본적으로 알아야합니다.
테스트 데이터 50,000 개의 10kb 파일을 만들었습니다 (이는 처리중인 파일의 평균 파일 크기를 반영합니다).
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
가능한 한 간단하게 2 개의 스크립트를 만들었습니다.
Perl
foreach my $file (<$ARGV[0]/*.xml>){
my $fh;
open($fh, "< $file");
my $contents = do { local $/; <$fh> };
close($fh);
}
파이썬
import glob, sys
for file in glob.iglob(sys.argv[1] + '/*.xml'):
with open(file) as x:
f = x.read()
그런 다음 캐시를 지우고 2 개의 slurp 스크립트를 실행했습니다. 각 실행 사이에 다음을 사용하여 캐시를 다시 정리했습니다.
sync; sudo sh -c 'echo 3 > /proc/sys/vm/drop_caches'
그런 다음 매번 디스크에서 모든 것을 읽고 있는지 모니터링했습니다.
sudo iotop -a -u me
저는 RAID 10 디스크가있는 물리적 시스템에서이를 시도했으며 VM이 RAID 1 SSD에있는 새로운 VM에서 물리적 서버가 훨씬 더 빠르기 때문에 내 VM에서 테스트 실행을 포함했습니다.
$ 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
Perl이 DISK READ를 실행할 때 약 45M / s이고 IOWAIT가 약 70 % 일 때 iotop에서 발견했습니다. Python DISK READ를 실행할 때 2M / s이고 IOWAIT 97 %였습니다. 내가 얻을 수있는 한 간단하게 끓여서 여기서 어디로 가야할지 모르겠습니다.
관련이있는 경우
$ 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
요청 된 추가 정보
strace를 실행하고 1000.xml 파일에 대한 정보를 가져 왔지만 모두 동일한 작업을 수행하는 것 같습니다.
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>
파이썬
$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>
관련성이 있는지 확실하지 않은 한 가지 차이점은 Perl이 파일을 열기 시작하기 전에 모든 파일에 대해 실행하는 것처럼 보이지만 파이썬은 그렇지 않다는 것입니다.
32303 lstat("2/1000.xml", {st_mode=S_IFREG|0664, st_size=10000, ...}) = 0 <0.000022>
또한 -c를 사용하여 strace를 실행했습니다.
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
파이썬
$ 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
-T를 켜고 각 파일에 대해 처음 8192 바이트를 읽은 상태에서 strace 출력을 일부 구문 분석 했습니까? 이것이 시간이가는 곳이라는 것이 분명합니다. 아래는 파일을 처음 읽는 50000 회에 소요 된 총 시간입니다. 각 읽기에 대한 평균 시간.
300.247128000002 (0.00600446220302379) - Python
11.6845620000003 (0.000233681892724297) - Perl
도움이되는지 확실하지 않습니다!
업데이트 2 Python에서 os.open 및 os.read를 사용하고 처음 4096 바이트의 단일 읽기만 수행하도록 업데이트 된 코드 (내가 원하는 정보가 파일의 상단 부분에 있으므로 저에게 효과적 임)는 다른 모든 호출을 제거합니다. 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)
여전히 나아지지 않습니다 ... 다음으로 Azure에서 VM을 만들고 다른 예를 들어 보겠습니다!
업데이트 3-이것의 크기에 대한 사과 !!
세 가지 설정에서 (@JFSebastian) 스크립트를 사용하여 흥미로운 결과를 확인하고, 간결성을 위해 시작시 출력을 제거하고 캐시에서 매우 빠르게 실행되고 다음과 같은 모든 테스트를 제거했습니다.
0.23user 0.26system 0:00.50elapsed 99%CPU (0avgtext+0avgdata 9140maxresident)k
0inputs+0outputs (0major+2479minor)pagefaults 0swaps
Azure A2 표준 VM (2 코어 3.5GB RAM 디스크 알 수 없지만 느림)
$ 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
둘 다에 대해 비교 가능한 첫 번째 slurp 결과, 2nd Perl slurp 동안 무슨 일이 벌어 졌는지 확실하지 않습니까?
내 VMWare Linux VM (2 코어 8GB RAM 디스크 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
이번에는 이전과 마찬가지로 Perl이 첫 번째 slurp에서 훨씬 빠르며, 이전에는이 동작을 보지 못했지만 두 번째 Perl slurp에서 무슨 일이 일어나고 있는지 확실하지 않습니다. measure.sh를 다시 실행하고 결과는 정확히 동일하거나 몇 초가 걸립니다. 그런 다음 일반 사람이 수행하는 작업을 수행하고 Azure 머신 3.13.0-35-generic과 일치하도록 커널을 업데이트하고 measure.sh를 다시 실행하고 결과에 차이를 만들지 않았습니다.
호기심에서 나는 measure.sh에서 1과 2 매개 변수를 바꿨고 이상한 일이 발생했습니다. Perl 속도가 느려지고 Python 속도가 빨라졌습니다!
+ /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
이것은 나를 더 혼란스럽게 만들었습니다 :-(
물리적 서버 (32 코어 132GB 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
여기서 Perl은 매번이기는 것 같습니다.
당황한
내 로컬 VM에서 이상한 점을 감안할 때 내가 가장 많이 제어 할 수있는 시스템 인 디렉터리를 교체 할 때 데이터 디렉터리로 1 또는 2를 사용하여 python 대 perl을 실행할 수있는 모든 옵션에 대해 바이너리 접근 방식을 시도 할 것입니다. 일관성을 위해 여러 번 실행하려고 시도하지만 시간이 좀 걸리고 조금 미쳐가므로 먼저 휴식이 필요할 수 있습니다! 내가 원하는 것은 일관성입니다 :-(
업데이트 4-일관성
(아래는 ubuntu-14.04.1-server VM에서 실행되며 커널은 3.13.0-35-generic # 62-Ubuntu입니다)
나는 일관성을 찾았다 고 생각하며 Python / Perl을 위해 가능한 모든 방법으로 테스트를 실행하여 데이터 디렉토리 1/2에서 다음을 발견했습니다.
- Python은 생성 된 파일에서 항상 느립니다 (예 : dd에 의해 생성됨).
- Python은 복사 된 파일에서 항상 빠릅니다 (예 : cp -r로 생성됨).
- Perl은 생성 된 파일 (예 : dd에 의해 생성됨)에서 항상 빠릅니다.
- Perl은 복사 된 파일에서 항상 느립니다 (예 : cp -r에 의해 생성됨).
그래서 OS 레벨 복사를 살펴 보았는데 우분투에서 'cp'가 Python과 같은 방식으로 동작하는 것 같습니다. 즉, 원본 파일에서는 느리고 복사 된 파일에서는 빠릅니다.
이것이 내가 실행 한 결과이며 단일 SATA HD가있는 컴퓨터와 RAID10 시스템에서이 작업을 몇 번 수행 한 결과 :
$ 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
추적 결과는 시간이 소비되는 곳을 보여줍니다.
$ 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
So it seems copying copies is much faster than copying original files, my current guess is that when copied the files get aligned on disk better than when they were originally created making them more efficient to read?
Interestingly 'rsyn' and 'cp' seem to work in opposite ways speedwise, much like Perl and 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
I will focus on only one of your examples, because rest things should be analogical:
What I think, may matter in this situation is Read-Ahead (or maybe another technique related to this) feature:
Let consider such example:
I have created 1000 xml files in "1" dir (names 1.xml to 1000.xml) as you did by dd command and then I copied orginal dir 1 to 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
In the next step I debugged cp command (by strace) to found out in what order data are copied:
So cp does it in following order (only first 4 files, because I saw that the second read from original directory is more time consuming that second read from copied directory)
100.xml 150.xml 58.xml 64.xml ... * in my example
Now, take a look on filesystem blocks which are used by these files (debugfs output - ext3 fs):
Original directory:
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
....
As you can see, in the "Copied directory" the block are adjacent, so it means that during reading of the first file 100.xml the "Read Ahead" technique (controller or system settings) can increase performance.
dd create file in order 1.xml to 1000.xml, but cp command copies it in another order (100.xml, 150.xml, 58.xml,64.xml). So when you execute:
cp -r 1 1copy
to copy this dir to another, the blocks of files which you are copied are not adjacent, so read of such files take more time.
When you copy dir which you copied by cp command (so files are not created by dd command), then file are adjacent so creating:
cp -r 2 2copy
copy of the copy is faster.
Summary: So to test performance python/perl you should use the same dir (or two dirs copied by cp command) and also you can use option O_DIRECT to read bypassing all kernel buffers and read data from disk directly.
Please remember, that results can be different on different type of kernel, system, disk controller, system settings, fs and so on.
Additions:
[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:
참고URL : https://stackoverflow.com/questions/26178038/python-slow-read-performance-issue
'programing' 카테고리의 다른 글
| RecyclerView에 스크롤 할 콘텐츠가 충분하지 않지만 AppBarLayout의 도구 모음을 스크롤 할 수 있습니다. (0) | 2020.12.02 |
|---|---|
| 기기의 시간 프로파일 러가 작동하지 않습니다. (0) | 2020.12.02 |
| C ++ and, or, not, xor 키워드 (0) | 2020.12.02 |
| AngularJS에서 정렬 가능한 ng : repeats 드래그 앤 드롭? (0) | 2020.12.01 |
| HTML 페이지의 div에 외부 웹 페이지를로드하는 방법 (0) | 2020.12.01 |