Why is Hugo slow the first time I run it every day?

0 of 2 drafts rendered
0 future content 
304 pages created
0 paginator pages created
285 tags created
14 categories created
28 places created
4 langs created
2 menu created
in 380 ms
1.11u 0.37s 0.80r 23148kB hugo

I have only run it once … but it was my first … 0.8 is “real time” from the time command.

Is there anything I can do to debug why it takes longer for me? To find out what it is actually doing during those 30 seconds?

What OS do you run on?

Arch Linux 64 bits

strace should give you a hint.

Dang. Can’t extract 7zip on this Mac.

The output of strace is 64Mb and half million lines :slight_smile: What should I look at?

Hard to say – in your case I would look for what it doesn’t do for 30 seconds. There should be some obious waiting between some syscalls… But now I’m guessing.

strace -c -o first.log

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 94.08    0.082186           0    551439           read
  3.87    0.003382           1      4967       402 futex
  1.98    0.001728          32        54           getdents64
  0.04    0.000034           0      3554         4 stat
  0.02    0.000019           0      1250           open
  0.01    0.000009           0       596         1 lstat
  0.00    0.000000           0       106           write
  0.00    0.000000           0      1254           close
  0.00    0.000000           0         9           fstat
  0.00    0.000000           0         9           mmap
  0.00    0.000000           0         1           munmap
  0.00    0.000000           0        58           rt_sigaction
  0.00    0.000000           0        15           rt_sigprocmask
  0.00    0.000000           0        78           sched_yield
  0.00    0.000000           0         3           socket
  0.00    0.000000           0         2           bind
  0.00    0.000000           0         2           setsockopt
  0.00    0.000000           0         7           clone
  0.00    0.000000           0         1           execve
  0.00    0.000000           0         1           mkdir
  0.00    0.000000           0         1           sigaltstack
  0.00    0.000000           0         1           arch_prctl
  0.00    0.000000           0         1           sched_getaffinity
------ ----------- ----------- --------- --------- ----------------
100.00    0.087358                563409       407 total


strace -c -o second.log

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 91.40    0.002847           0    552066           read
  7.87    0.000245           0      3968       263 futex
  0.51    0.000016           0      3537         2 stat
  0.22    0.000007           0      1559           close
  0.00    0.000000           0        78           write
  0.00    0.000000           0      1557           open
  0.00    0.000000           0       323           fstat
  0.00    0.000000           0       921         3 lstat
  0.00    0.000000           0        13           mmap
  0.00    0.000000           0         1           munmap
  0.00    0.000000           0        58           rt_sigaction
  0.00    0.000000           0        15           rt_sigprocmask
  0.00    0.000000           0        75           sched_yield
  0.00    0.000000           0         3           socket
  0.00    0.000000           0         2           bind
  0.00    0.000000           0         2           setsockopt
  0.00    0.000000           0         7           clone
  0.00    0.000000           0         1           execve
  0.00    0.000000           0         1           sigaltstack
  0.00    0.000000           0         1           arch_prctl
  0.00    0.000000           0         1           sched_getaffinity
  0.00    0.000000           0        75           getdents64
------ ----------- ----------- --------- --------- ----------------
100.00    0.003115                564264       268 total

I don’t know how to interpret these. The first run did take about half minute, but the output seems to indicate 0.08 seconds. The second run was definitely faster, and it shows 0.003 seconds. What do these numbers mean?

Sorry, I used 7z because the file size is half. If I remember right 7z notices when files are duplicated, but zip doesn’t.

What drive do you have on this machine?

A 256 Gb SSD with FDE.

Is this a separate run or using watch?

Also how large is the output directory?

Just “hugo”, no watch.

Running du -h tells me the public/ folder is 609 Mb.

My “version” of your blog:

271M    ./public

Ha! Fixed!

You are right @bjornerik, that’s the right size. I had the .7z copy of the blog inside public. I deleted it, and then went and deleted each orfan file I had laying around inside public and now, after many months, it seems to be fixed! It was done before I finished lifting the finger from the enter key :slight_smile:

Maybe having a hundred random files in subfolders inside public/ causes a big delay the first time you run hugo?

It tries to synchronize the directories. If there are a lot of files or really large files it will take some time to copy them over.

But that would not explain why it’s slow only once after booting, even if the files did not change, or?

The synchronizing only seems to add new and changed files, but does not delete extra files. My impression is that it was those extra files that caused the slowness.

I just tried again with hugo 0.14. The more verbose output is useful. I can see that it’s stuck at “INFO: 2015/07/16 syncing from /home/xxx/www/yyy.com/static/ to /home/xxx/www/yyy.com/public/” for about half minute. static is 245 Mb.

@spf13 - How does hugo determine if a file has changed? A brief explanation and a pointer to that could would be useful.

I’m curious if that interaction is part of the problem. Hashing large files or some such…