what if native systemd service is slower than old sysvinit script?

Thu Sep 15 07:15:20 UTC 2011

2011/9/14 Tom Lane <tgl at redhat.com>:
> =?ISO-8859-2?Q?Micha=B3_Piotrowski?= <mkkp4x4 at gmail.com> writes:
>> Ok, I made four series of tests:
>> - start/stop an old init script
>> - start/stop an old init script with dropping caches - should simulate
>> system booting
>> - start/stop service file
>> - start/stop service file with dropping caches
>
>> In each series of tests were repeated five times.
>> series 1 - start - 2.2+ sec
>> series 1 - stop - 1.2+ sec
>
>> series 2 - start - 2.4+ sec
>> series 2 - stop - 1.3+ sec
>
>> series 3 - start - 3.1+ sec
>> series 3 - stop - 1.1+ sec
>
>> series 4 - start - 4.2+ sec
>> series 4 - stop - 1.1+ sec
>
>> Results are reproducible.
>
> I tried to replicate these results on my own F15 laptop, and could not
> --- the service file method doesn't really seem significantly faster
> than the init script, but it's not slower either.
>
> Here's what I did:
>
> 1. Install the postgresql-9.1.0 RPMs (rebuilt for F15 of course)
>   and do "postgresql-setup initdb".

I did the same thing, just with PGSQL 9.0

>
> 2. Set log_line_prefix = '%m %p ' and log_connections = on in
> postgresql.conf, so that log messages will be timestamped.  Also set
> timezone and log_timezone to desired values (I use 'US/Eastern');
> if you don't do that, the server startup time is increased significantly
> while Postgres tries to figure out the system timezone setting.

I also changed these parameters

>
> 3. As root, do
> date --rfc-3339=ns ; systemctl start postgresql.service ; date --rfc-3339=ns

with dropped cache

date --rfc-3339=ns ; systemctl start postgresql.service ; date --rfc-3339=ns
2011-09-15 08:44:40.348239703+02:00
2011-09-15 08:44:44.651134587+02:00

without dropped cache
date --rfc-3339=ns ; systemctl start postgresql.service ; date --rfc-3339=ns
2011-09-15 08:45:38.388010217+02:00
2011-09-15 08:45:42.633229665+02:00

>
> 4. Note the time from the first "date" output to the "database system is
> ready to accept connections" message getting logged (in the appropriate
> file under /var/lib/pgsql/data/pg_log, if you haven't changed any other
> logging settings).  Stop and restart a few times to get a good average.
>
> 5. Install the F15 version of postgresql.init (be sure to adjust the
> PGVERSION setting near the top of the file to be 9.1.0).
>
> 6. Start it that way a few times, note the same elapsed time.
>
> I'm seeing numbers consistently around 0.3 second for the unit file,
> and a bit less consistent but maybe 0.35 - 0.5 second for the script.
>

Ok, this is good news, because it seems that this behavior only occurs
on my system. Also Jef Spaleta can not repeat this behavior of
service.

> Note that the time for the service to report itself ready after the
> database has started is likely to be quite a bit different between the
> two methods, but that is not systemd's fault.  The init script just
> launches the postmaster, sleeps for 2 seconds, and then reports "OK"
> if it sees the postmaster has created a PID file.  The unit file uses
> pg_ctl, which actually waits till it can make a successful connection
> to the postmaster, sleeping 1 second between tries.  So it's a bit of a
> crapshoot which will be longer, though if you are starting from a clean
> database shutdown I'd expect pg_ctl to usually come back after the first
> sleep.
>
> So I'm not sure what's happening on Michal's machine, but from here I
> don't see anything egregiously wrong with systemd's performance on
> this test.

I tried to figureout what is happening with strace. I don't see any
significant difference between start with an old init script and
service file. I wonder just what's going on with "Resource temporarily
unavailable" - it seems to me that if I use service, it wait's a bit
longer (but I'm not able to measure time, so it can only be an
impression).

ioctl(0, SNDCTL_TMR_TIMEBASE or SNDRV_TIMER_IOCTL_NEXT_DEVICE or
TCGETS, {B38400 opost isig icanon echo ...}) = 0
clone(child_stack=0,
flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD,
child_tidptr=0x7f1ef78cea90) = 3934
sendmsg(3, {msg_name(0)=NULL,
msg_iov(2)=[{"l\1\0\1$\0\0\0\1\0\0\0\240\0\0\0\1\1o\0\31\0\0\0/org/fre"...,
176}, {"\22\0\0\0postgresql.service\0\0\7\0\0\0repl"..., 36}],
msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 212
poll([{fd=3, events=POLLIN}], 1, 25000) = 1 ([{fd=3, revents=POLLIN}])
recvmsg(3, {msg_name(0)=NULL,
msg_iov(1)=[{"l\2\1\1'\0\0\0\1\0\0\0\17\0\0\0\5\1u\0\1\0\0\0\10\1g\0\1o\0\0"...,
2048}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC},
MSG_CMSG_CLOEXEC) = 71
recvmsg(3, 0x7fffe59f6a10, MSG_CMSG_CLOEXEC) = -1 EAGAIN (Resource
temporarily unavailable)
sendmsg(3, {msg_name(0)=NULL,
msg_iov(2)=[{"l\1\0\1\27\0\0\0\2\0\0\0\227\0\0\0\1\1o\0\31\0\0\0/org/fre"...,
168}, {"\22\0\0\0postgresql.service\0", 23}], msg_controllen=0,
msg_flags=0}, MSG_NOSIGNAL) = 191
poll([{fd=3, events=POLLIN}], 1, 25000) = 1 ([{fd=3, revents=POLLIN}])
recvmsg(3, {msg_name(0)=NULL,
msg_iov(1)=[{"l\4\1\1+\0\0\0\2\0\0\0\203\0\0\0\1\1o\0\31\0\0\0/org/fre"...,
2048}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC},
MSG_CMSG_CLOEXEC) = 283
recvmsg(3, 0x7fffe59f6a10, MSG_CMSG_CLOEXEC) = -1 EAGAIN (Resource
temporarily unavailable)
sendmsg(3, {msg_name(0)=NULL,
msg_iov(2)=[{"l\1\0\0019\0\0\0\3\0\0\0\250\0\0\0\1\1o\0003\0\0\0/org/fre"...,
184}, {"\35\0\0\0org.freedesktop.systemd1.Uni"..., 57}],
msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 241
poll([{fd=3, events=POLLIN}], 1, 25000) = 1 ([{fd=3, revents=POLLIN}])
recvmsg(3, {msg_name(0)=NULL,
msg_iov(1)=[{"l\2\1\1\10\0\0\0\4\0\0\0\17\0\0\0\5\1u\0\3\0\0\0\10\1g\0\1v\0\0"...,
2048}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC},
MSG_CMSG_CLOEXEC) = 40
recvmsg(3, 0x7fffe59f6a10, MSG_CMSG_CLOEXEC) = -1 EAGAIN (Resource
temporarily unavailable)
poll([{fd=3, events=POLLIN}], 1, -1)    = 1 ([{fd=3, revents=POLLIN}])
recvmsg(3, {msg_name(0)=NULL,
msg_iov(1)=[{"l\4\1\0015\0\0\0\5\0\0\0\223\0\0\0\1\1o\0\31\0\0\0/org/fre"...,
2048}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC},
MSG_CMSG_CLOEXEC) = 221
recvmsg(3, 0x7fffe59f6c40, MSG_CMSG_CLOEXEC) = -1 EAGAIN (Resource
temporarily unavailable)

>
>                        regards, tom lane
> --
> devel mailing list
> devel at lists.fedoraproject.org
> https://admin.fedoraproject.org/mailman/listinfo/devel
>

-- 
Best regards,
Michal

http://eventhorizon.pl/