2

How to get date/time of these events:

  • last system hibernate / suspend
  • last system resume
1

You could examine your system log file /var/log/syslog for messages indicating suspend/hibernate/resume events and look at their timestamps.

For suspend and resume, check e.g. this pattern:

grep -E 'PM: suspend (entry|exit)' /var/log/syslog

Example output:

Sep  8 09:43:26 type40mark3 kernel: [150509.893804] PM: suspend entry (deep)
Sep  8 15:03:39 type40mark3 kernel: [150514.147721] PM: suspend exit
Sep  8 16:33:41 type40mark3 kernel: [155914.275076] PM: suspend entry (deep)
Sep  8 17:04:58 type40mark3 kernel: [155919.343276] PM: suspend exit

This only checks the current syslog file, but as it is subject to log rotation, older messages will be archived in numbered and compressed files like /var/log/syslog.1 and /var/log/syslog.2.gz. To check all of these at once, use zgrep instead, which can read compressed files, and sort to get them back in order by the actual timestamp date:

zgrep -hE 'PM: suspend (entry|exit)' /var/log/syslog* | sort -M

To get only the last two lines (last suspend and resume, usually), you can append | tail -n 2 to either of the above commands.

If you want only suspend or only resume, alter the filter pattern to e.g. PM: suspend entry or PM: suspend exit accordingly.


I don't have a hibernating system available right now to search for appropriate messages for that event, but I expect something similar. Try searching e.g. grep hiber /var/log/syslog to find a suitable pattern. When you have one, please comment and I'll gladly add it to this answer for future reference.

Pay attention to the timestamps though and compare them with the actual real times you know, because some of the "late" messages like systemd[1]: Started Suspend. can be triggered right before the system actually turns off, but will actually be logged and written to disk with the timestamp of when it turns on again.

  • 1
    You were absolutely right about dmesg. Indeed, it does not keep count of how much time the system has been suspended for. That makes my answer not appropriate for what the OP wants to do, that's why I deleted it. Your answer, despite being the only one, seems to be the best for the job. Just one note: perhaps you could update your answer to only show the last suspend/resume event, since that's what the OP asked for. Thanks again for pointing out the dmesg limitation. – user3140225 Sep 9 at 8:11
  • @user3140225 Thanks, I added some notes about that. Sorry that the effort you put into writing the script for your answer seemingly was in vain. – Byte Commander Sep 9 at 14:23
  • No worries. I learned something in the process: never trust dmesg timestamps! – user3140225 Sep 9 at 15:11
  • Another problem in the dmesg based solution is that atleast in Ubuntu 16 dmesg default settings are such that event is cleared / not found after few ours. – user4955663 Sep 9 at 16:23
  • On Ubuntu 16 it seems that "PM: suspend" and "PM: resume" events both are written into syslog during resume. So the suspend time in your solution is incorrectly same as the resume time. However, the resume time is correct. – user4955663 Sep 9 at 16:38
0

As I commented Byte Commader's response, for some reason atleast on my two Ubuntu 16 installations it seems that "PM: suspend" and "PM: resume" events both are written into syslog during resume. So the suspend time in that solution is within one second same as the resume time. However, the resume time is correct.

So this solution is not based on log files. It is based on very simple service running continuously and monitoring time difference before and after a sleep. If the difference is much bigger than sleep time then there has been a "pause", e.g. suspend/resume operation. Pause is logged after wakeup when the time is synced.

pauselogger.sh

set -e

if [[ "$#" < 1 || "$#" > 1 ]]
then
    echo "Illegal number of parameters"
    echo "Usage $0 <sleeptime in seconds>"
    exit 1
fi

sleepTime=$1
fileName="/var/log/state.log"

dateStr1=$(date "+%Y-%m-%d %T.%N %z %s")
dateInt1=$(echo $dateStr1 | cut -d' ' -f4)
dateInt2=$dateInt1
dateStr2=$dateStr1
diff=0
for (( ; ; ))
do
    diff="$(($dateInt1-$dateInt2))"
    maxDiff=$(echo $sleepTime*1.1 + 1 | bc) # Pause is 10% longer than sleep.
    if (( $(echo "$diff > $maxDiff" |bc -l) )); then  
        echo "$dateStr2 DOWN pre sleep" >> $fileName
        echo "$dateStr1 UP post sleep $diff" >> $fileName       
    fi

    dateStr2=$dateStr1
    dateInt2=$dateInt1

    sleep $sleepTime

    dateStr1=$(date "+%Y-%m-%d %T.%N %z %s")
    dateInt1=$(echo $dateStr1 | cut -d' ' -f4)

done

Service definition is also simple file: /etc/systemd/system/pauselogger.service

[Unit]
Description=Simple Pause Logger

[Service]
ExecStart=/usr/sbin/pauselogger.sh 30
Restart=on-failure

[Install]
WantedBy=multi-user.target

Logger is then started and enabled:

sudo systemctl start pauselogger
sudo systemctl enable pauselogger

Log file:

2019-09-13 00:44:17.602146211 +0300 1568324657 UP post sleep 225
2019-09-13 01:04:59.968326886 +0300 1568325899 DOWN pre sleep
2019-09-13 10:25:18.575107533 +0300 1568359518 UP post sleep 33619
2019-09-13 10:49:41.594151484 +0300 1568360981 DOWN pre sleep
2019-09-13 10:51:57.129617072 +0300 1568361117 UP post sleep 136

Pros of this solution is that it works despite the pause command. It records pauses if OS level suspend/hibernate/resume is used, but it also works if used inside a VM, e.g. VirtualBox savestate/resume.

Cons are atleast that both log entries are written during wakeup, this solution is not suitable e.g. if a script is needed to be launched just before savestate operation. Also the command causing sleep/wakeup is not recorded: OS suspend vs VirtualBox savestate or OS resume vs VirtualBox start.

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.