Comando Shell lento ao usar pipe, rápido com arquivo intermediário

19

Alguém entende essa enorme diferença no tempo de processamento, ao usar um arquivo intermediário ou ao usar um pipe? Estou convertendo tiff para pdf usando ferramentas padrão em um novo servidor debian squeeze. Uma maneira padrão de fazer isso é converter primeiro em ps.

Sem tubo:

root@web5:~# time tiff2ps test.tif > test.ps

real    0m0.860s
user    0m0.744s
sys 0m0.112s

root@web5:~# time ps2pdf13 -sPAPERSIZE=a4 test.ps > test.pdf

real    0m0.667s
user    0m0.612s
sys 0m0.060s

Com tubo:

root@web5:~# time tiff2ps test.tif | ps2pdf13 -sPAPERSIZE=a4 - > test.pdf

real    1m6.098s
user    0m15.861s
sys 0m50.9

Durante o último comando, o processo gs está 100% o tempo todo.

Atualização :
Aqui está uma saída strace para a geração ps:

root@web5:~# strace tiff2ps test.tif > test.ps
execve("/usr/bin/tiff2ps", ["tiff2ps", "test.tif"], [/* 28 vars */]) = 0
brk(0)                                  = 0x1395000
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fb5a1937000
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY)      = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=21735, ...}) = 0
mmap(NULL, 21735, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7fb5a1931000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/usr/lib/libtiff.so.4", O_RDONLY) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0P\200\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0644, st_size=405128, ...}) = 0
mmap(NULL, 2501416, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7fb5a14b9000
mprotect(0x7fb5a151a000, 2093056, PROT_NONE) = 0
mmap(0x7fb5a1719000, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x60000) = 0x7fb5a1719000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/usr/lib/libjpeg.so.62", O_RDONLY) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\3408\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0644, st_size=145048, ...}) = 0
mmap(NULL, 2240080, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7fb5a1296000
mprotect(0x7fb5a12b9000, 2093056, PROT_NONE) = 0
mmap(0x7fb5a14b8000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x22000) = 0x7fb5a14b8000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/usr/lib/libz.so.1", O_RDONLY)    = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\260\"\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0644, st_size=93936, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fb5a1930000
mmap(NULL, 2188976, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7fb5a107f000
mprotect(0x7fb5a1096000, 2093056, PROT_NONE) = 0
mmap(0x7fb5a1295000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x16000) = 0x7fb5a1295000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/lib/libm.so.6", O_RDONLY)        = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\360>\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0644, st_size=530736, ...}) = 0
mmap(NULL, 2625768, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7fb5a0dfd000
mprotect(0x7fb5a0e7d000, 2097152, PROT_NONE) = 0
mmap(0x7fb5a107d000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x80000) = 0x7fb5a107d000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/lib/libc.so.6", O_RDONLY)        = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\240\355\1\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=1437064, ...}) = 0
mmap(NULL, 3545160, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7fb5a0a9b000
mprotect(0x7fb5a0bf4000, 2093056, PROT_NONE) = 0
mmap(0x7fb5a0df3000, 20480, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x158000) = 0x7fb5a0df3000
mmap(0x7fb5a0df8000, 18504, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7fb5a0df8000
close(3)                                = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fb5a192f000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fb5a192e000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fb5a192d000
arch_prctl(ARCH_SET_FS, 0x7fb5a192e700) = 0
mprotect(0x7fb5a0df3000, 16384, PROT_READ) = 0
mprotect(0x7fb5a107d000, 4096, PROT_READ) = 0
mprotect(0x7fb5a1939000, 4096, PROT_READ) = 0
munmap(0x7fb5a1931000, 21735)           = 0
open("test.tif", O_RDONLY)              = 3
brk(0)                                  = 0x1395000
brk(0x13b6000)                          = 0x13b6000
read(3, "II*\0\10\0\0\0", 8)            = 8
fstat(3, {st_mode=S_IFREG|0644, st_size=1825656, ...}) = 0
mmap(NULL, 1825656, PROT_READ, MAP_SHARED, 3, 0) = 0x7fb5a176f000
open("/proc/meminfo", O_RDONLY)         = 4
fstat(4, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fb5a1936000
read(4, "MemTotal:        2090844 kB\nMemF"..., 1024) = 1024
close(4)                                = 0
munmap(0x7fb5a1936000, 4096)            = 0
write(2, "TIFFReadDirectory: ", 19TIFFReadDirectory: )     = 19
write(2, "Warning, ", 9Warning, )                = 9
write(2, "test.tif: wrong data type 7 for "..., 59test.tif: wrong data type 7 for "RichTIFFIPTC"; tag ignored) = 59
write(2, ".\n", 2.
)                      = 2
gettimeofday({1334836895, 374666}, NULL) = 0
fstat(1, {st_mode=S_IFREG|0664, st_size=0, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fb5a1936000
open("/etc/localtime", O_RDONLY)        = 4
fstat(4, {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
fstat(4, {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fb5a1935000
read(4, "TZif2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\4\0\0\0\4\0\0\0\0"..., 4096) = 1892
lseek(4, -1217, SEEK_CUR)               = 675
read(4, "TZif2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\6\0\0\0\6\0\0\0\0"..., 4096) = 1217
close(4)                                = 0
munmap(0x7fb5a1935000, 4096)            = 0
write(1, "%!PS-Adobe-3.0 EPSF-3.0\n%%Creato"..., 4096) = 4096
write(1, "fffffffffffffffffffffffffffff\nff"..., 4096) = 4096
write(1, "ffffffffffffffffffff\nfffffffffff"..., 4096) = 4096
write(1, "fffffffffff\nffffffffffffffffffff"..., 4096) = 4096
write(1, "ff\nfffffffffffffffffffffffffffff"..., 4096) = 4096
write(1, "ffffffffffffffffffffffffffffffff"..., 4096) = 4096
write(1, "ffffffffffffffffffffffffffffffff"..., 4096) = 4096
write(1, "ffffffffffffffffffffffffffffffff"..., 4096) = 4096
write(1, "ffffffffffffffffffffffffffffffff"..., 4096) = 4096
write(1, "ffffffffffffffffffffffff\nfffffff"..., 4096) = 4096

Aqui está uma saída strace para a versão canalizada: a geração do PS parece ser muito mais lenta quando a saída é canalizada no ps2pdf13. 

root@web5:~# strace tiff2ps test.tif | ps2pdf13 -sPAPERSIZE=a4 - > test.pdf
execve("/usr/bin/tiff2ps", ["tiff2ps", "test.tif"], [/* 28 vars */]) = 0
brk(0)                                  = 0x1b97000
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f9208bb1000
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY)      = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=21735, ...}) = 0
mmap(NULL, 21735, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f9208bab000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/usr/lib/libtiff.so.4", O_RDONLY) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0P\200\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0644, st_size=405128, ...}) = 0
mmap(NULL, 2501416, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f9208733000
mprotect(0x7f9208794000, 2093056, PROT_NONE) = 0
mmap(0x7f9208993000, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x60000) = 0x7f9208993000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/usr/lib/libjpeg.so.62", O_RDONLY) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\3408\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0644, st_size=145048, ...}) = 0
mmap(NULL, 2240080, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f9208510000
mprotect(0x7f9208533000, 2093056, PROT_NONE) = 0
mmap(0x7f9208732000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x22000) = 0x7f9208732000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/usr/lib/libz.so.1", O_RDONLY)    = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\260\"\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0644, st_size=93936, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f9208baa000
mmap(NULL, 2188976, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f92082f9000
mprotect(0x7f9208310000, 2093056, PROT_NONE) = 0
mmap(0x7f920850f000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x16000) = 0x7f920850f000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/lib/libm.so.6", O_RDONLY)        = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\360>\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0644, st_size=530736, ...}) = 0
mmap(NULL, 2625768, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f9208077000
mprotect(0x7f92080f7000, 2097152, PROT_NONE) = 0
mmap(0x7f92082f7000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x80000) = 0x7f92082f7000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/lib/libc.so.6", O_RDONLY)        = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\240\355\1\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=1437064, ...}) = 0
mmap(NULL, 3545160, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f9207d15000
mprotect(0x7f9207e6e000, 2093056, PROT_NONE) = 0
mmap(0x7f920806d000, 20480, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x158000) = 0x7f920806d000
mmap(0x7f9208072000, 18504, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f9208072000
close(3)                                = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f9208ba9000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f9208ba8000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f9208ba7000
arch_prctl(ARCH_SET_FS, 0x7f9208ba8700) = 0
mprotect(0x7f920806d000, 16384, PROT_READ) = 0
mprotect(0x7f92082f7000, 4096, PROT_READ) = 0
mprotect(0x7f9208bb3000, 4096, PROT_READ) = 0
munmap(0x7f9208bab000, 21735)           = 0
open("test.tif", O_RDONLY)              = 3
brk(0)                                  = 0x1b97000
brk(0x1bb8000)                          = 0x1bb8000
read(3, "II*\0\10\0\0\0", 8)            = 8
fstat(3, {st_mode=S_IFREG|0644, st_size=1825656, ...}) = 0
mmap(NULL, 1825656, PROT_READ, MAP_SHARED, 3, 0) = 0x7f92089e9000
open("/proc/meminfo", O_RDONLY)         = 4
fstat(4, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f9208bb0000
read(4, "MemTotal:        2090844 kB\nMemF"..., 1024) = 1024
close(4)                                = 0
munmap(0x7f9208bb0000, 4096)            = 0
write(2, "TIFFReadDirectory: ", 19TIFFReadDirectory: )     = 19
write(2, "Warning, ", 9Warning, )                = 9
write(2, "test.tif: wrong data type 7 for "..., 59test.tif: wrong data type 7 for "RichTIFFIPTC"; tag ignored) = 59
write(2, ".\n", 2.
)                      = 2
gettimeofday({1334836513, 114140}, NULL) = 0
fstat(1, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f9208bb0000
open("/etc/localtime", O_RDONLY)        = 4
fstat(4, {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
fstat(4, {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f9208baf000
read(4, "TZif2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\4\0\0\0\4\0\0\0\0"..., 4096) = 1892
lseek(4, -1217, SEEK_CUR)               = 675
read(4, "TZif2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\6\0\0\0\6\0\0\0\0"..., 4096) = 1217
close(4)                                = 0
munmap(0x7f9208baf000, 4096)            = 0
write(1, "%!PS-Adobe-3.0 EPSF-3.0\n%%Creato"..., 4096) = 4096
write(1, "fffffffffffffffffffffffffffff\nff"..., 4096) = 4096
write(1, "ffffffffffffffffffff\nfffffffffff"..., 4096) = 4096
write(1, "fffffffffff\nffffffffffffffffffff"..., 4096) = 4096
write(1, "ff\nfffffffffffffffffffffffffffff"..., 4096) = 4096
write(1, "ffffffffffffffffffffffffffffffff"..., 4096) = 4096
write(1, "ffffffffffffffffffffffffffffffff"..., 4096) = 4096
write(1, "ffffffffffffffffffffffffffffffff"..., 4096) = 4096
write(1, "ffffffffffffffffffffffffffffffff"..., 4096) = 4096
...etc...
linux bash scripting shell-scripting pipe plang
fonte
Esses arquivos são grandes?
Khaled
Não, de forma alguma: 1,8 MB para o arquivo tiff.
plang
2
@ plang: Você já tentou straceo processo gs? Talvez seja o processamento do arquivo em pedaços maiores ao usar o arquivo intermediário, ou algo semelhante acontece ...
Janne Pikkarainen
Você pode fornecer a versão específica do Ghostscript? gs -v
precisa saber é
1
Aqui está o tiff: sendspace.com/file/vqoxbs
plang

Respostas:

17

Editar: executei isso com seu arquivo de origem no meu ambiente e tenho os seguintes resultados:

[root@xt ~]# time tiff2ps test.tif > test.ps
real    0m0.795s
user    0m0.659s
sys     0m0.135s

[root@xt ~]# time ps2pdf13 -sPAPERSIZE=a4 test.ps > test.pdf
real    0m0.592s
user    0m0.513s
sys     0m0.075s

[root@xt ~]# time tiff2ps test.tif | ps2pdf13 -sPAPERSIZE=a4 - > test2.pdf
real    0m13.110s
user    0m4.601s
sys     0m7.260s

Eu adicionei o pvcomando para ver o que estava acontecendo. Aqui está o que aconteceu:

[root@xt ~]# time tiff2ps test.tif | pv | ps2pdf13 -sPAPERSIZE=a4 - > test2.pdf
50.5MB 0:00:12 [4.05MB/s] [                      <=>                                                               ]

real    0m13.934s
user    0m4.751s
sys     0m8.261s

50 megabytes de saída Postscript sendo canalizados para o ps2pdf13comando! @janneb estava correto, pois este é um problema de buffer / pipe. Tentei alavancar o unbuffercomando , mas o Ghostscript não gosta do pseudoterminal.

Existe algum motivo para você não poder usar o tiff2pdfcomando?

[root@xt ~]# time tiff2pdf -o test2.pdf test.tif

real    0m0.242s
user    0m0.176s
sys     0m0.064s
ewwhite
fonte
Há uma diferença que posso ver, mas menos importante do que no meu arquivo de teste de 1,8 MB.
plang
1
Olá, acho que você encontrou o problema. Obrigado! Eu não sabia que o tiff2pdf existia. Funciona muito rápido, mas há um problema: a saída tem 26 MB de tamanho, em comparação com 356K no tiff2ps / ps2pdf13.
plang
1
Executá-lo com compressão JPEG (384 K): tiff2pdf -j -o test.pdf test.tifou ZIP compressão (1,6 M):tiff2pdf -z -o test3.pdf test.tif
ewwhite
1
O tiff2pdf com as opções "-j" corrige o problema de tamanho.
plang