Home / ubuntu / Questions / 1171742
Accepted
user4955663
Asked: 2019-09-09 05:47:56 +0800 CST

How to get date/time of the last system hibernate / suspend / resume?

  • 772

How to get date/time of these events:

  • last system hibernate / suspend
  • last system resume
suspend hibernate resume

2 Answers

  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.

    • 9
  2. Best Answer

    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.

    • 0