LINUX.ORG.RU

Низкая производительность файловых операций PHP

 , , , ,


3

5

Есть сайт на битриксе на дедике.

И в этот самый битрикс встроена функция тестирования производительнсти система. Один из тестов - скорость файловых операций - подсчитывается сколько за секунду может быть создано, заинклюжено и удалено файлов. Нормой считается 10000. По факту хорошая система на SSD выдает 40-50 тысяч (специально взял VDSку и проверил).

Однако на вышеупомянутом сайте это число не больше 20000, а в срденем вообще в районе той самой хилой нормы. При этот деди имеет два интеловских nvme в рейд1.

root@site ~# hdparm -t /dev/md126 

/dev/md126:
 Timing buffered disk reads: 2532 MB in  3.00 seconds = 843.80 MB/sec
root@site ~# sync; dd if=/dev/zero of=tempfile bs=1M count=1024; sync
1024+0 записей получено
1024+0 записей отправлено
 скопировано 1073741824 байта (1,1 GB), 0,672519 c, 1,6 GB/c

Из самой системы вроде все неплохо. С рандомным доступом тоже все хорошо.

Но тесты в PHP плохие. Выковырнул код теста в отдельный скрипт: https://pastebin.com/f8NW8JKv

Прогнал его на специально купленной VDS (server2) и подопытном (server1):

bitrix@server2 ~> php www/file_test.php
17076.859502993

user@sever1 ~/w/mysite.ru> php _test/file_test.php
11523.489278892

При этом тесты производительности из системы показывают в два раза меньшую скорость на server2, а server1 в тестах PHP показывают в 5 раз меньшую скорость.

Т.е. тормозит именно PHP. При этом и там и там 7.4.21. И там и там CentOS 7 и ядро 3.10 что-тот там. Настройки переносить пробовал. Модули php активированные делал идентичными наборами - ничего не помогает.

Я похоже не один такой: https://dev.1c-bitrix.ru/support/forum/forum32/topic86027/

Куда копать?

UPD:

Ранее были не совсем верные данные по скриптам при запуске из консоли, разница не такая ощутимая, как при запуске из вэб интерфейса где продакшен проигрывает 15000 к 44000.

Сейчас данные тестов из коносли честные.

UPD2: Низкая производительность файловых операций PHP (комментарий)

Я похоже не один такой

ЛОЛ, а ещё говорят ЛОР токсичный…

тормозит именно PHP

А ты уверен, что именно IO? Там в тесте какой-то треш с генерацией кода и последующим его чтением. Я б на твоём месте сделал тест отдельно на чтение-запись без выгибонов. А этот убертест прогнал бы в профайлере, чтобы посмотреть что там различается между серверами.

no-such-file ★★★★★ ()
Ответ на: комментарий от no-such-file

А ты уверен, что именно IO? Там в тесте какой-то треш с генерацией кода и последующим его чтением. Я б на твоём месте сделал тест отдельно на чтение-запись без выгибонов.

Там видишь во втором блоке тест из консоли запущен и у него два выхлопа - второй Without include - так вот это оно.

Suntechnic ★★★★★ ()
Ответ на: комментарий от int13h

Запускал. Вот например:

# fio -ioengine=libaio -fsync=1 -direct=1 -name=test -bs=4k -iodepth=1 -rw=write -runtime=60 -filename=/random_file 
test: (g=0): rw=write, bs=(R) 4096B-4096B, (W) 4096B-4096B, (T) 4096B-4096B, ioengine=libaio, iodepth=1
fio-3.7
Starting 1 process
Jobs: 1 (f=1): [W(1)][100.0%][r=0KiB/s,w=226MiB/s][r=0,w=57.9k IOPS][eta 00m:00s]
test: (groupid=0, jobs=1): err= 0: pid=55915: Mon Jul 19 01:39:33 2021
  write: IOPS=49.4k, BW=193MiB/s (202MB/s)(8192MiB/42472msec)
    slat (usec): min=2, max=10811, avg= 3.88, stdev= 9.37
    clat (nsec): min=419, max=3429.5k, avg=10629.53, stdev=8385.86
     lat (usec): min=9, max=10861, avg=14.61, stdev=12.76
    clat percentiles (nsec):
     |  1.00th=[ 7968],  5.00th=[ 8096], 10.00th=[ 8256], 20.00th=[ 8512],
     | 30.00th=[ 8640], 40.00th=[ 8640], 50.00th=[ 9024], 60.00th=[ 9536],
     | 70.00th=[ 9792], 80.00th=[10304], 90.00th=[12224], 95.00th=[15936],
     | 99.00th=[43776], 99.50th=[48896], 99.90th=[64256], 99.95th=[80384],
     | 99.99th=[96768]
   bw (  KiB/s): min=120344, max=236144, per=100.00%, avg=201888.17, stdev=27028.64, samples=82
   iops        : min=30086, max=59036, avg=50472.01, stdev=6757.15, samples=82
  lat (nsec)   : 500=0.01%, 750=0.01%, 1000=0.01%
  lat (usec)   : 2=0.01%, 4=0.01%, 10=75.35%, 20=21.14%, 50=3.09%
  lat (usec)   : 100=0.39%, 250=0.01%, 500=0.01%, 750=0.01%
  lat (msec)   : 2=0.01%, 4=0.01%
  fsync/fdatasync/sync_file_range:
    sync (nsec): min=23, max=19393, avg=61.01, stdev=60.31
    sync percentiles (nsec):
     |  1.00th=[   40],  5.00th=[   42], 10.00th=[   43], 20.00th=[   46],
     | 30.00th=[   48], 40.00th=[   50], 50.00th=[   52], 60.00th=[   58],
     | 70.00th=[   62], 80.00th=[   66], 90.00th=[   83], 95.00th=[  109],
     | 99.00th=[  161], 99.50th=[  199], 99.90th=[  402], 99.95th=[  652],
     | 99.99th=[  884]
  cpu          : usr=14.62%, sys=31.89%, ctx=4194226, majf=0, minf=34
  IO depths    : 1=200.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwts: total=0,2097152,0,2097151 short=0,0,0,0 dropped=0,0,0,0
     latency   : target=0, window=0, percentile=100.00%, depth=1

Run status group 0 (all jobs):
  WRITE: bw=193MiB/s (202MB/s), 193MiB/s-193MiB/s (202MB/s-202MB/s), io=8192MiB (8590MB), run=42472-42472msec

Disk stats (read/write):
    md126: ios=18/4269683, merge=0/0, ticks=0/0, in_queue=3416331696, util=100.00%, aggrios=9/2181156, aggrmerge=0/41866, aggrticks=1/17316, aggrin_queue=17318, aggrutil=97.13%
  nvme0n1: ios=17/2181156, merge=0/41866, ticks=3/17507, in_queue=17510, util=97.13%
  nvme1n1: ios=1/2181156, merge=0/41866, ticks=0/17126, in_queue=17126, util=97.11%
Suntechnic ★★★★★ ()
Ответ на: комментарий от fernandos

Низкая производительность файловых операций PHP (комментарий)

Да и проблема точно в РНР?

Похоже что да.

Я пробовал разные тесты скорости - в том числе fio - производительность дисков на проде выше чем на тестовом сервере, который взял специально. Я пробовал запускать тесты и от имени пользователя от которого выполняется PHP сайта - та же картина - прод быстрее минимум вдвое - так я исключил, как я считаю, системную проблема с вводом выводом.

Я запускал тесты из консоли, на слуйча если проблема скажем в модуле апач (мало ли?). Включил/отключал opcache. Отрубил все лишние модули PHP на проде. Пробовал идентичный конфиг PHP (разве что не модулей - просто php.ini)

Дальше куда копать не знаю. Хоть прод новый покупать и там с нуля все настраивать.

Suntechnic ★★★★★ ()

Этот «тест» до диска вообще не доходит, он в кеше ворочается. Соответственно результат от диска не зависит никак, упираясь в скорость одного ядра CPU и памяти.
Хотите высоких показателей в пузомерке - ставьте битрих на десктопное железо и отрубайте энергосбережение.

NeOlip ★★ ()

Поддерживаю регистранта селинукс когда есть apparmor не нужен и вообще должен быть перемещен целиком и полностью в андроид не место этой тормозящей блоатваре в убунту да и в линуксах

anonymous ()
Ответ на: комментарий от fernandos

РНР стоит из реми?

Там стоял 7.4.19 в /opt, возможно самосборный, а системным был 5.4. Я в начале на это и грешил. Поставил из реми и даже стало лучше - раньше выше 8000 вообще в тесте не поднималось, а сейчас 12-16 тысяч обычно. Уж не знаю что помогло - обновление до 7.14.21 или пыха из реми.

я бы не доверял.

А какая разница если тесты идентичные на обоих машинах?

Suntechnic ★★★★★ ()

Вы знаете, ваш тест какой-то странный.

Я его несколько изменил:

<?php

$res = [];
$file_name = __DIR__ . "/test/perfmon#i#.php";
$content = '<?php $s="' . str_repeat("x", 1024) . '";?><?php /* ' . str_repeat("y", 1024) . '*/?><?php $r="' . str_repeat("z", 1024) . '";?>';
printf("CONTENT_VAR: %s\n", $content);

for ($j = 0; $j < 4; $j++) {
    $start1 = hrtime(true) / 1000000000;
    for ($i = 0; $i < 20000; $i++) {
        $fn = str_replace("#i#", $i, $file_name);
    }
    $end1 = hrtime(true) / 1000000000;
    $time1 = $end1 - $start1;
    $start2 = hrtime(true) / 1000000000;
    for ($i = 0; $i < 20000; $i++) {
        //This is one op
        $fileName = str_replace("#i#", $i, $file_name);
        $file = fopen($fileName, "wb");
        fwrite($file, $content);
        fclose($file);
        include $fileName;
        unlink($fileName);
    }
    $end2 = hrtime(true) / 1000000000;
    $time2 = $end2 - $start2;
    if ($time2 > $time1) {
        $res[] = 20000 / ($time2 - $time1);
    }
}
printf("%f\n", array_sum($res) / count($res));
system('rm -rf test/*');

и, если я не ошибся, то что-то тут не так. Тестирую на винчестере: 20364.022957, теперь в тмпфс: 30880.991187. Выглядит как бред. При этом, если я тестирую на жёстком диске, я не вижу должного горения индикатора работы диска. Теперь комментирую строку unlink($fileName);, результаты: винчестер: 17881.399733, тмпфс: 46680.186303, уже больше похоже на правду.

Это я к тому, что сам тест достаточно странный.

fernandos ★★ ()
Ответ на: комментарий от NeOlip

Прод:

# 7za b -mmt1

7-Zip (a) [64] 16.02 : Copyright (c) 1999-2016 Igor Pavlov : 2016-05-21
p7zip Version 16.02 (locale=ru_RU.UTF-8,Utf16=on,HugeFiles=on,64 bits,36 CPUs Intel(R) Xeon(R) W-2295 CPU @ 3.00GHz (50657),ASM,AES-NI)

Intel(R) Xeon(R) W-2295 CPU @ 3.00GHz (50657)
CPU Freq:  1407  1775  2086  2363  2702  2984  2984  2980  3931

RAM size:   63970 MB,  # CPU hardware threads:  36
RAM usage:    435 MB,  # Benchmark threads:      1

                       Compressing  |                  Decompressing
Dict     Speed Usage    R/U Rating  |      Speed Usage    R/U Rating
         KiB/s     %   MIPS   MIPS  |      KiB/s     %   MIPS   MIPS

22:       5470   100   5325   5322  |      50429   100   4305   4306
23:       4935   100   5007   5029  |      49329   100   4272   4270
24:       4420   100   4754   4753  |      47706   100   4185   4188
25:       4193   100   4788   4788  |      47459   100   4223   4224
----------------------------------  | ------------------------------
Avr:             100   4968   4973  |              100   4246   4247
Tot:             100   4607   4610

Suntechnic ★★★★★ ()
Ответ на: комментарий от Suntechnic

Контроль:

7za b -mmt1

7-Zip (a) [64] 16.02 : Copyright (c) 1999-2016 Igor Pavlov : 2016-05-21
p7zip Version 16.02 (locale=ru_RU.UTF-8,Utf16=on,HugeFiles=on,64 bits,1 CPU QEMU Virtual CPU version 4.2.0 (306A9),ASM,AES-NI)

QEMU Virtual CPU version 4.2.0 (306A9)
CPU Freq:  2633  2670  2662  2665  2648  2668  2542  2644  2626

RAM size:    1998 MB,  # CPU hardware threads:   1
RAM usage:    435 MB,  # Benchmark threads:      1

                       Compressing  |                  Decompressing
Dict     Speed Usage    R/U Rating  |      Speed Usage    R/U Rating
         KiB/s     %   MIPS   MIPS  |      KiB/s     %   MIPS   MIPS

22:       1765    93   1839   1718  |      21168    81   2229   1807
23:       2087    99   2140   2127  |      25888    98   2279   2241
24:       1516    98   1670   1630  |      25984   100   2287   2281
25:       1378    96   1648   1574  |      23972    99   2159   2134
----------------------------------  | ------------------------------
Avr:              96   1825   1762  |               94   2239   2116
Tot:              95   2032   1939
Suntechnic ★★★★★ ()
Ответ на: комментарий от fernandos

Он не мой - я выковырял его из недр битрикс. И я не вижу принципиальной разницы в том как он сделан. Я вижу проблему в том что на более мощном, гораздо более мощном железе, я получаю гораздо более низкие цифры на одном и том же тесте.

Suntechnic ★★★★★ ()
Ответ на: комментарий от goingUp

Млин, у меня бомбит от этого васянского теста, что аж в тред вернулся. Ну чтение ок, но напуркуа бенчить запись и удаление мелких файлов. Гм, удаление… Может дело в TRIM? Лол.

Топовая российская компания наняла студентов-третьекурсников, ага.

goingUp ★★★★★ ()
Ответ на: комментарий от goingUp

Ну чтение ок, но напуркуа бенчить запись и удаление мелких файлов.

Так это просто бенч папугаев. Типа тестирование железа - оно ни на что не влияет и нужно типа для галочки.

А запись и удаление нужно бенчить для получение предстовления о создании кэша если кэш в файлах. Если не изменяет память уже 2010 году этот бенч был и вряд ли он сильно поменялся за это время.

Suntechnic ★★★★★ ()
Ответ на: комментарий от goingUp

Млин, у меня бомбит от этого васянского теста, что аж в тред вернулся. Ну чтение ок, но напуркуа бенчить запись и удаление мелких файлов. Гм, удаление… Может дело в TRIM? Лол.

На самом деле я уже довольно давно (пару недель) ломаю голов на проблемой, периодически возвращаясь к ней и конечно TRIM одно из первых что пришло в голову. Я просто убирал удаление - оставлял только создание - те же сравнительные результаты. Только инклюд - тоже похоже, но там сильное влияние опкэш я думаю. Только удаление я тоже пробовал.

Suntechnic ★★★★★ ()
Ответ на: комментарий от func

Не сильно в этом разбираюсь.

Вот контроль:

990.65210693592
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 21,80    0,013704           4      2807       403 lstat
 18,76    0,011792          11      1010        30 open
 14,57    0,009158          22       400           unlink
 10,26    0,006452          16       402           write
  6,61    0,004155          11       349           mmap
  6,53    0,004106           4       984           close
  5,45    0,003427           3      1034           fstat
  5,16    0,003242          13       236           mprotect
  4,92    0,003092           5       573           read
  3,50    0,002201          13       158           munmap
  1,94    0,001222           3       401           lseek
  0,34    0,000212           2        72        25 stat
  0,14    0,000086           2        33           brk
  0,02    0,000014           2         6           futex
  0,02    0,000010           5         2           getrandom
  0,00    0,000000           0        80           rt_sigaction
  0,00    0,000000           0         2           rt_sigprocmask
  0,00    0,000000           0        47        47 ioctl
  0,00    0,000000           0         4         2 access
  0,00    0,000000           0         1           execve
  0,00    0,000000           0         2           getdents
  0,00    0,000000           0         1           getcwd
  0,00    0,000000           0         2           getrlimit
  0,00    0,000000           0         2         2 statfs
  0,00    0,000000           0         1           arch_prctl
  0,00    0,000000           0         1           set_tid_address
  0,00    0,000000           0         1           clock_getres
  0,00    0,000000           0         1           openat
  0,00    0,000000           0         1           set_robust_list
------ ----------- ----------- --------- --------- ----------------
100.00    0,062873                  8613       509 total

А это продакшен:

1807.1266469827
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 35,12    0,022139           5      4010       403 lstat
 13,41    0,008452           8       989        35 open
  8,71    0,005491          13       401           unlink
  7,69    0,004848           4       996           fstat
  7,49    0,004723           4       959           close
  6,28    0,003958          29       132           munmap
  5,19    0,003270           8       402           write
  4,97    0,003133           5       549           read
  3,01    0,001897           6       303         1 mmap
  2,89    0,001823           4       401           lseek
  2,49    0,001569           7       206           mprotect
  0,96    0,000605           7        81           rt_sigaction
  0,65    0,000410           7        56        22 stat
  0,42    0,000267           7        35        35 ioctl
  0,24    0,000149          37         4           getdents
  0,21    0,000133           4        31           brk
  0,08    0,000052           4        12           fcntl
  0,04    0,000028           5         5         3 access
  0,04    0,000026          13         2           openat
  0,03    0,000017           5         3           futex
  0,02    0,000012           6         2           getrandom
  0,02    0,000011          11         1           getcwd
  0,01    0,000009           9         1           arch_prctl
  0,01    0,000009           9         1           gettid
  0,01    0,000005           2         2           rt_sigprocmask
  0,00    0,000000           0         1           execve
  0,00    0,000000           0         1           fchmod
  0,00    0,000000           0         2           getrlimit
  0,00    0,000000           0         2         2 statfs
  0,00    0,000000           0         1           set_tid_address
  0,00    0,000000           0         1           clock_getres
  0,00    0,000000           0         1           set_robust_list
------ ----------- ----------- --------- --------- ----------------
100.00    0,063036                  9593       501 total

Прошу обратить внимание на апдейт в шапке.

Кстати с strace продакше быстрее.

Suntechnic ★★★★★ ()
Ответ на: комментарий от Suntechnic
root@myshop ~# php /var/www/my/data/www/myshop.ru/_test/file_test.php
11736.534005856
root@myshop ~# php file_test.php 
16131.285180353
root@myshop ~# php /var/www/my/data/www/myshop.ru/_test/file_test.php
11362.454177328
root@myshop ~# php file_test.php 
15853.759319604
root@myshop ~# php /var/www/my/data/www/myshop.ru/_test/file_test.php
11481.994787481
root@myshop ~# php file_test.php 
15455.95201139
root@myshop ~# php /var/www/my/data/www/myshop.ru/_test/file_test.php
11396.493794729
root@myshop ~# php file_test.php 
16028.22253946
root@myshop ~# php /var/www/my/data/www/myshop.ru/_test/file_test.php
11676.519562157
root@myshop ~# php file_test.php 
16379.334872677
root@myshop ~# php /var/www/my/data/www/myshop.ru/_test/file_test.php
11470.815876339

Потому что на продакшене:

lstat("/var/www/my/data/www/myshop.ru/_test/../upload/perfmon99.php", 0x7fffcba92150) = -1 ENOENT (Нет такого файла или каталога)
lstat("/var/www/my/data/www/myshop.ru/_test/../upload", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
lstat("/var/www/my/data/www/myshop.ru/_test", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
lstat("/var/www/my/data/www/myshop.ru", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
lstat("/var/www/my/data/www", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
lstat("/var/www/my/data", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
lstat("/var/www/my", {st_mode=S_IFDIR|0501, st_size=4096, ...}) = 0
lstat("/var/www", {st_mode=S_IFDIR|0751, st_size=4096, ...}) = 0
lstat("/var", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0

А на контроле:

lstat("/home/bitrix/www/_test/../upload/perfmon92.php", 0x7ffef6c70ab0) = -1 ENOENT (Нет такого файла или каталога)
lstat("/home/bitrix/www/_test/../upload", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
lstat("/home/bitrix/www/_test", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
lstat("/home/bitrix/www", {st_mode=S_IFDIR|0770, st_size=4096, ...}) = 0
lstat("/home/bitrix", {st_mode=S_IFDIR|0700, st_size=4096, ...}) = 0
lstat("/home", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0

Кто-то может это объяснить? Почему lstat рекурсивно до корня выполняется?

Suntechnic ★★★★★ ()
Ответ на: комментарий от Suntechnic

Итак, проблема - результат вызова lstat рекурсивно для пути по которому происходит open если файл не существует. В итоге на серверах с большей вложенностью пути, мы получаем худшие показатели.

В моем случае путь к документрут на сервере контроле: /home/bitrix/www/ (так как это BitrixVM), а на продакшене вроде такого /var/www/my/data/www/myshop.ru/. Т.е. 3 токена против 6.

Проверим теорию поместив скрипт тест в /root на продакшене:

root@myshop ~# php /var/www/my/data/www/myshop.ru/_test/file_test.php
11736.534005856
root@myshop ~# php file_test.php 
16131.285180353
root@myshop ~# php /var/www/my/data/www/myshop.ru/_test/file_test.php
11362.454177328
root@myshop ~# php file_test.php 
15853.759319604

Похоже на это действительно так. Поробуем сравнить работу штатного скрипта и скрипта из который будет только инклюдить созданные файлы:

root@server2 ~> php /home/bitrix/www/_test/file_test.php
17076.859502993

root@sever1 ~> /var/www/soho/data/www/myshop.ru/_test/file_test.php
11523.489278892
Контроль (server1) уверенно лидирует. Пробуем только инклюд:

root@server2 ~# php /home/bitrix/www/_test/file_test.php
51052.618943912

root@sever1 ~# php /var/www/soho/data/www/myshop.ru/_test/file_test.php
188870.92855328

И вот тут raid1 на nvme полностью раскрывает свои возможности.

Короче этот тест - просто попугаемерка имеющая мало практического значения, если сравнивать серверы на которых вложенность документрут разная.

На практике важна скорость доступа для include, а вовсе не создание несуществующего файла, если только у вас не создается кэш на каждом вызове, но тогда какой в не смысл?

Suntechnic ★★★★★ ()
Ответ на: комментарий от Suntechnic

Почему lstat рекурсивно до корня выполняется?

Это так работает определение realpath. В норме это должно кэшироваться, но возможны варианты, особенно если в пути есть символические ссылки. Также кэш отключается в safe_mode или если установлен open_basedir.

no-such-file ★★★★★ ()
Ответ на: комментарий от func

тогда php по-моему вообще не будет кэшировать результат выполнения stat команд

Ну это надо специально так сделать, по умолчанию кэш включён и он довольно большой в последних версиях пыха.

no-such-file ★★★★★ ()