Bug #77536 [Com]: finfo considerably slower on 7.3 vs. 7.2

Edit report at https://bugs.php.net/bug.php?id=77536&edit=1 ID: 77536 Comment by: jscaltreto at gmail dot com Reported by: jscaltreto at gmail dot com Summary: finfo considerably slower on 7.3 vs. 7.2 Status: Open Type: Bug Package: Filesystem function related PHP Version: 7.3.1 Block user comment: N Private report: N New Comment: Here is an strace (strace -ttT) from just before I call finfo->file() in 7.2: 15:13:08.781506 write(1, "MARKSTART", 9) = 9 <0.000127> 15:13:08.781814 lstat("/bin/sh", {st_mode=S_IFLNK|0777, st_size=4, ...}) = 0 <0.000010> 15:13:08.781986 readlink("/bin/sh", "dash", 4096) = 4 <0.000012> 15:13:08.782172 lstat("/bin/dash", {st_mode=S_IFREG|0755, st_size=117208, ...}) = 0 <0.000075> 15:13:08.782393 lstat("/bin", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0 <0.000027> 15:13:08.782614 open("/bin/dash", O_RDONLY) = 3 <0.000085> 15:13:08.782866 fstat(3, {st_mode=S_IFREG|0755, st_size=117208, ...}) = 0 <0.000068> 15:13:08.783073 lseek(3, 0, SEEK_CUR) = 0 <0.000009> 15:13:08.783272 fstat(3, {st_mode=S_IFREG|0755, st_size=117208, ...}) = 0 <0.000068> 15:13:08.783463 fstat(3, {st_mode=S_IFREG|0755, st_size=117208, ...}) = 0 <0.000065> 15:13:08.783657 read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\2407\0\0\0\0\0\0"..., 8192) = 8192 <0.000074> 15:13:08.783886 read(3, "\10\0\0\0\0\0\0\0\31`\1\0\0\0\0\0@\267!\0\0\0\0\0\10\0\0\0\0\0\0\0"..., 8192) = 8192 <0.000058> 15:13:08.784123 read(3, "\367\333I\211E\0\350\305\4\0\0D\211\347A\211\304\351\347\376\377\377f.\17\37\204\0\0\0\0\0"..., 8192) = 8192 <0.000055> 15:13:08.784336 read(3, "\6\0\0L\211\353E1\344\17\37\200\0\0\0\0\272\3\0\0\0L\211\356L\211\367\350@9\0\0"..., 8192) = 8192 <0.000077> 15:13:08.784545 read(3, "C!\0H\215=3\316\0\0H9\305t\24H\215P\1H9\325\17\204\204\1\0\0\306E\377\0"..., 8192) = 8192 <0.000061> 15:13:08.784744 read(3, "\5\327)!\0\235\377\377\377\307\5QJ!\0\235\377\377\377\270~\377\377\377\351h\377\377\377\17\37\0"..., 8192) = 8192 <0.000029> 15:13:08.784971 read(3, "I\213G H\211\2H\213\5\272\3!\0H\205\300\17\204R\1\0\0\200x\36\1t\21\351G\1"..., 8192) = 8192 <0.000010> 15:13:08.785190 read(3, "\203\351 \0\1u\n\213\5\213\351 \0\205\300u\0171\300H\203\304\10\303\17\37\204\0\0\0\0\0"..., 8192) = 8192 <0.000054> 15:13:08.785413 read(3, "H\213\35A\300 \0\351\347\367\377\377\213\5\22\355 \0\203\5\v\300 \0\1\205\300\17\204p\374\377"..., 8192) = 8192 <0.000072> 15:13:08.785647 read(3, "$8H\215l$@I\203\305\10L\211-\266\246 \0H\211D$\10H\215E\4H\211D$\30"..., 8192) = 8192 <0.000077> 15:13:08.785873 read(3, "H\205\377u\34\3534f\17\37\204\0\0\0\0\0H\203\303\10\350W:\377\377H\213;H\205\377t"..., 8192) = 8192 <0.000078> 15:13:08.786095 read(3, "MAX-12\0RTMAX-11\0RTMAX-10\0RTMAX-9"..., 8192) = 8192 <0.000057> 15:13:08.786316 read(3, "B\16(\214\5D\0160\206\6A\0168\203\7P\16\300\2\3!\1\n\0168A\0160A\16(B"..., 8192) = 8192 <0.000030> 15:13:08.786542 read(3, "\16\10\0\0\0\0\0\0\24\0\0\0\f2\0\0\260\246\377\377\35\0\0\0\0\0\0\0\0\0\0\0"..., 8192) = 8192 <0.000079> 15:13:08.786767 read(3, "\0\0\0\0\0\0\0\0\10\300!\0\0\0\0\0\240\354!\0\0\0\0\0\240\354!\0\0\0\0\0"..., 8192) = 2520 <0.000028> 15:13:08.786989 read(3, "", 8192) = 0 <0.000057> 15:13:08.787207 mmap(NULL, 937984, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f163d189000 <0.000030> 15:13:08.787562 lseek(3, 117208, SEEK_SET) = 117208 <0.000078> 15:13:08.787882 munmap(0x7f163d189000, 937984) = 0 <0.000087> 15:13:08.788118 close(3) = 0 <0.000010> 15:13:08.788354 write(1, "MARKEND", 7) = 7 <0.000093> 15:13:08.788638 write(1, "Took: 0.0071139335632324\n", 25) = 25 <0.000042> And here's the same trace for php-7.3: 15:13:09.822814 write(1, "MARKSTART", 9) = 9 <0.000082> 15:13:09.822984 lstat("/bin/sh", {st_mode=S_IFLNK|0777, st_size=4, ...}) = 0 <0.000089> 15:13:09.823168 readlink("/bin/sh", "dash", 4096) = 4 <0.000011> 15:13:09.823296 lstat("/bin/dash", {st_mode=S_IFREG|0755, st_size=117208, ...}) = 0 <0.000015> 15:13:09.823435 lstat("/bin", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0 <0.000011> 15:13:09.823573 open("/bin/dash", O_RDONLY) = 3 <0.000013> 15:13:09.823676 fstat(3, {st_mode=S_IFREG|0755, st_size=117208, ...}) = 0 <0.000009> 15:13:09.823826 lseek(3, 0, SEEK_CUR) = 0 <0.000008> 15:13:09.823968 fstat(3, {st_mode=S_IFREG|0755, st_size=117208, ...}) = 0 <0.000302> 15:13:09.824354 fstat(3, {st_mode=S_IFREG|0755, st_size=117208, ...}) = 0 <0.000069> 15:13:09.824518 read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\2407\0\0\0\0\0\0"..., 8192) = 8192 <0.000035> 15:13:09.824658 read(3, "\10\0\0\0\0\0\0\0\31`\1\0\0\0\0\0@\267!\0\0\0\0\0\10\0\0\0\0\0\0\0"..., 8192) = 8192 <0.000011> 15:13:09.824794 read(3, "\367\333I\211E\0\350\305\4\0\0D\211\347A\211\304\351\347\376\377\377f.\17\37\204\0\0\0\0\0"..., 8192) = 8192 <0.000009> 15:13:09.824893 read(3, "\6\0\0L\211\353E1\344\17\37\200\0\0\0\0\272\3\0\0\0L\211\356L\211\367\350@9\0\0"..., 8192) = 8192 <0.000010> 15:13:09.825039 read(3, "C!\0H\215=3\316\0\0H9\305t\24H\215P\1H9\325\17\204\204\1\0\0\306E\377\0"..., 8192) = 8192 <0.000011> 15:13:09.825182 read(3, "\5\327)!\0\235\377\377\377\307\5QJ!\0\235\377\377\377\270~\377\377\377\351h\377\377\377\17\37\0"..., 8192) = 8192 <0.000011> 15:13:09.825330 read(3, "I\213G H\211\2H\213\5\272\3!\0H\205\300\17\204R\1\0\0\200x\36\1t\21\351G\1"..., 8192) = 8192 <0.000011> 15:13:09.825483 read(3, "\203\351 \0\1u\n\213\5\213\351 \0\205\300u\0171\300H\203\304\10\303\17\37\204\0\0\0\0\0"..., 8192) = 8192 <0.000021> 15:13:09.825622 read(3, "H\213\35A\300 \0\351\347\367\377\377\213\5\22\355 \0\203\5\v\300 \0\1\205\300\17\204p\374\377"..., 8192) = 8192 <0.000021> 15:13:09.825736 read(3, "$8H\215l$@I\203\305\10L\211-\266\246 \0H\211D$\10H\215E\4H\211D$\30"..., 8192) = 8192 <0.000018> 15:13:09.825879 read(3, "H\205\377u\34\3534f\17\37\204\0\0\0\0\0H\203\303\10\350W:\377\377H\213;H\205\377t"..., 8192) = 8192 <0.000010> 15:13:09.826013 read(3, "MAX-12\0RTMAX-11\0RTMAX-10\0RTMAX-9"..., 8192) = 8192 <0.000020> 15:13:09.826153 read(3, "B\16(\214\5D\0160\206\6A\0168\203\7P\16\300\2\3!\1\n\0168A\0160A\16(B"..., 8192) = 8192 <0.000027> 15:13:09.826287 read(3, "\16\10\0\0\0\0\0\0\24\0\0\0\f2\0\0\260\246\377\377\35\0\0\0\0\0\0\0\0\0\0\0"..., 8192) = 8192 <0.000010> 15:13:09.826425 read(3, "\0\0\0\0\0\0\0\0\10\300!\0\0\0\0\0\240\354!\0\0\0\0\0\240\354!\0\0\0\0\0"..., 8192) = 2520 <0.000009> 15:13:09.826559 read(3, "", 8192) = 0 <0.000009> 15:13:09.826679 mmap(NULL, 2097152, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f5368189000 <0.000013> 15:13:09.826776 munmap(0x7f5368189000, 2097152) = 0 <0.000021> 15:13:09.826947 mmap(NULL, 4190208, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f5367f8a000 <0.000010> 15:13:09.827063 munmap(0x7f5367f8a000, 483328) = 0 <0.000028> 15:13:09.827186 munmap(0x7f5368200000, 1609728) = 0 <0.000009> 15:13:09.827267 madvise(0x7f5368000000, 2097152, MADV_HUGEPAGE) = 0 <0.000009> 15:13:10.101436 lseek(3, 117208, SEEK_SET) = 117208 <0.000014> 15:13:10.101930 close(3) = 0 <0.000021> 15:13:10.102099 write(1, "MARKEND", 7) = 7 <0.000066> 15:13:10.102309 write(1, "Took: 0.27948999404907\n", 23) = 23 <0.000085> There are a handful of additional memory calls in 7.3, but the calls themselves are very quick. The problem area actually appears to be between syscalls here: 15:13:09.827267 madvise(0x7f5368000000, 2097152, MADV_HUGEPAGE) = 0 <0.000009> 15:13:10.101436 lseek(3, 117208, SEEK_SET) = 117208 <0.000014> The madvise only takes 9us, but the timestamp of the next call is nearly 200ms later. Previous Comments: ------------------------------------------------------------------------ [2019-01-29 02:37:01] danack@php.net ah - Just read the actual run script. nvm about the docker compose. ------------------------------------------------------------------------ [2019-01-29 02:33:36] danack@php.net Please could you run the scripts through strace to identify the system call that is causing the difference: https://linux.die.net/man/1/strace Possibly also, although it might be clear to you what the official dockers images are, please could you link to them or name them as they are on docker hub. Or even better provide a Docker compose to run the two things through. ------------------------------------------------------------------------ [2019-01-28 23:57:04] jscaltreto at gmail dot com Description: ------------ Calls via finfo to lookup mimetype of files take 30%+ longer to run on php 7.3+ than on 7.2. In an extreme case on a cpu-loaded machine I've observed finfo->file() calls taking upwards of 500ms in 7.3, where on the same hardware with the same load the calls typically take <1ms for the same file in 7.2. The included test script can be executed in both 7.2 and 7.3 to illustrate the problem. I've also created a simple test using official docker images to reproduce the issue: https://gist.github.com/jscaltreto/8f6adf38e7abb08a831ef37b84c14ace Test script: --------------- <?php $iters = 1000; $start = microtime(true); for ($i = 1; $i <= $iters; $i++){ $finfo = new finfo(FILEINFO_MIME); $type = $finfo->file("/bin/sh"); unset($finfo); } $ttl = microtime(true) - $start; echo "Took: $ttl\n"; ?> Expected result: ---------------- 7.2 and 7.3 should execute the script in roughly the same amount of time. Actual result: -------------- 7.3 takes 30%+ more time to execute. ------------------------------------------------------------------------ -- Edit this bug report at https://bugs.php.net/bug.php?id=77536&edit=1