New: System becomes unresponsive when swapping - Regression since 4.10.x

(switched to email. Please respond via emailed reply-to-all, not via the bugzilla web interface).

So it's "Regression: yes". More info at the bugzilla link.

--
To unsubscribe, send a message with 'unsubscribe linux-mm' in the body to [email protected]. For more info on Linux MM,
see: http://www.linux-mm.org/ .
Don't email: <a href=mailto:"[email protected]"> [email protected] </a>

[...]

Please try to collect /proc/vmstat in the bacground and provide the collected data. Something like

while true
do

	cp /proc/vmstat > vmstat.$(date +%s)
	sleep 1s

done

If the system turns out so busy that it won't be able to fork a process or write the output (which you will see by checking timestamps of files and looking for holes) then you can try the attached proggy ./read_vmstat output_file timeout output_size

Note you might need to increase the mlock rlimit to lock everything into memory.

Michal Hocko
SUSE Labs

#define _GNU_SOURCE
#include <sys/types.h>
#include <sys/stat.h>
#include <sys/mman.h>
#include <errno.h>
#include <fcntl.h>
#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include <limits.h>
#include <unistd.h>
#include <time.h>

/*
* A simple /proc/vmstat collector into a file. It tries hard to guarantee
* that the content will get into the output file even under a strong memory
* pressure.
*
* Usage
* ./read_vmstat output_file timeout output_size
*
* output_file can be either a non-existing file or - for stdout
* timeout - time period between two snapshots. s - seconds, ms - miliseconds
* and m - minutes suffix is allowed
* output_file - size of the output file. The file is preallocated and pre-filled. *
* If the output reaches the end of the file it will start over overwriting the oldest
* data. Each snapshot is enclosed by header and footer.
* =S timestamp
* [...]
* E=
*
* Please note that your ulimit has to be sufficient to allow to mlock the code+
* all the buffers.
*
* This comes under GPL v2
* Copyright: Michal Hocko <[email protected]> 2015
*/

#define NS_PER_MS (1000*1000)
#define NS_PER_SEC (1000*NS_PER_MS)

int open_file(const char *str)

{
	int fd;

	fd = open(str, O_CREAT|O_EXCL|O_RDWR, 0755);
	if (fd == -1) {
		perror("open input");
		return 1;
	}

	return fd;
}

int read_timeout(const char *str, struct timespec *timeout)

{
	char *end;
	unsigned long val;

	val = strtoul(str, &end, 10);
	if (val == ULONG_MAX) {
		perror("Invalid number");
		return 1;
	}
	switch(*end) {
		case 's':
			timeout->tv_sec = val;
			break;
		case 'm':
			/* ms vs minute*/
			if (*(end+1) == 's') {
				timeout->tv_sec = (val * NS_PER_MS) / NS_PER_SEC;
				timeout->tv_nsec = (val * NS_PER_MS) % NS_PER_SEC;
			} else {
				timeout->tv_sec = val*60;
			}
			break;
		default:
			fprintf(stderr, "Uknown number %s\n", str);
			return 1;
	}

	return 0;
}

size_t read_size(const char *str)

{
	char *end;
	size_t val = strtoul(str, &end, 10);

	switch (*end) {
		case 'K':
			val <<= 10;
			break;
		case 'M':
			val <<= 20;
			break;
		case 'G':
			val <<= 30;
			break;
	}

	return val;
}

size_t dump_str(char *buffer, size_t buffer_size, size_t pos, const char *in, size_t size)

{
	size_t i;
	for (i = 0; i < size; i++) {
		buffer[pos] = in[i];
		pos = (pos + 1) % buffer_size;
	}

	return pos;
}

/* buffer == NULL -> stdout */
int __collect_logs(const struct timespec *timeout, char *buffer, size_t buffer_size)

{
	char buff[4096]; /* dump to the file automatically */
	time_t before, after;
	int in_fd = open("/proc/vmstat", O_RDONLY);
	size_t out_pos = 0;
	size_t in_pos = 0;
	size_t size = 0;
	int estimate = 0;

	if (in_fd == -1) {
		perror("open vmstat:");
		return 1;
	}

	/* lock everything in */
	if (mlockall(MCL_CURRENT) == -1) {
		perror("mlockall. Continuing anyway");
	}

	while (1) {
		before = time(NULL);

		size = snprintf(buff, sizeof(buff), "=S %lu\n", before);
		lseek(in_fd, 0, SEEK_SET);
		size += read(in_fd, buff + size, sizeof(buff) - size);
		size += snprintf(buff + size, sizeof(buff) - size, "E=\n");
		if (buffer && !estimate) {
			printf("Estimated %d entries fit to the buffer\n", buffer_size/size);
			estimate = 1;
		}

		/* Dump to stdout */
		if (!buffer) {
			printf("%s", buff);
		} else {
			size_t pos;
			pos = dump_str(buffer, buffer_size, out_pos, buff, size);
			if (pos < out_pos)
				fprintf(stderr, "%lu: Buffer wrapped\n", before);
			out_pos = pos;
		}

		after = time(NULL);

		if (after - before > 2) {
			fprintf(stderr, "%d: Snapshoting took %d!!!\n", before, after-before);
		}
		if (nanosleep(timeout, NULL) == -1)
			if (errno == EINTR)
				return 0;
		/* kick in the flushing */
		if (buffer)
			msync(buffer, buffer_size, MS_ASYNC);
	}
}

int collect_logs(int fd, const struct timespec *timeout, size_t buffer_size)

{
	unsigned char *buffer = NULL;

	if (fd != -1) {
		if (ftruncate(fd, buffer_size) == -1) {
			perror("ftruncate");
			return 1;
		}

		if (fallocate(fd, 0, 0, buffer_size) && errno != EOPNOTSUPP) {
			perror("fallocate");
			return 1;
		}

		/* commit it to the disk */
		sync();

		buffer = mmap(NULL, buffer_size, PROT_READ | PROT_WRITE,
				MAP_SHARED | MAP_POPULATE, fd, 0);
		if (buffer == MAP_FAILED) {
			perror("mmap");
			return 1;
		}
	}

	return __collect_logs(timeout, buffer, buffer_size);
}

int main(int argc, char **argv)

{
	struct timespec timeout = {.tv_sec = 1};
	int fd = -1;
	size_t buffer_size = 10UL<<20;

	if (argc > 1) {
		/* output file */
		if (strcmp(argv[1], "-")) {
			fd = open_file(argv[1]);
			if (fd == -1)
				return 1;
		}

		/* timeout */
		if (argc > 2) {
			if (read_timeout(argv[2], &timeout))
				return 1;

			/* buffer size */
			if (argc > 3) {
				buffer_size = read_size(argv[3]);
				if (buffer_size == -1UL)
					return 1;
			}
		}
	}
	printf("file:%s timeout:%lu.%lus buffer_size:%llu\n",
			(fd == -1)? "stdout" : argv[1],
			timeout.tv_sec, timeout.tv_nsec / NS_PER_MS,
			buffer_size);

	return collect_logs(fd, &timeout, buffer_size);
}

Thanks Michal,

I have upgraded PCs since I initially put together this data - however I was able to get strange behaviour by pulling out an 8Gb RAM stick in my new system
- leaving it with only 8Gb of RAM.

All these tests are performed with Fedora 26 and kernel 4.12.8-300.fc26.x86_64

I have attached 3 files with output.

8Gb-noswap.tar.gz contains the output of /proc/vmstat running on 8Gb of RAM with no swap. Under this scenario, I was expecting the OOM reaper to just kill the game when memory allocated became too high for the amount of physical RAM. Interestingly, you'll notice a massive hang in the output before the game is terminated. I didn't see this before.

8Gb-swap-on-file.tar.gz contains the output of /proc/vmstat still with 8Gb of RAM - but creating a file with swap on the PCIe SSD /swapfile with size 8Gb via:

	# dd if=/dev/zero of=/swapfile bs=1G count=8
	# mkswap /swapfile
	# swapon /swapfile

Some times (all in UTC+10):
23:58:30 - Start loading the saved game
23:59:38 - Load ok, all running fine
00:00:15 - Load Chrome
00:01:00 - Quit the game

The game seemed to run ok with no real issue - and a lot was swapped to the swap file. I'm wondering if it was purely the speed of the PCIe SSD that caused this appearance - as the creation of the file with dd completed at ~1.4GB/sec.

8Gb-swap-on-ssd.tar.gz contains adding a 32Gb SATA based SSD to the system and using the entire block device as swap via:

	# mkswap -f /dev/sda
	# swapon /dev/sda

There are many pauses and unresponsiveness issues while this was loading - however we eventually got there.

Some timings (all in UTC+10 again):
00:06:33 - Load the saved game
00:11:22 - Saved game loaded - somewhat responsive 00:12:00 - Load Chrome
00:13:07 - Quit the game + chrome

For the sake of information, the following is a speed test on the SSD in question:

# dd if=/dev/zero of=/dev/sda bs=1M count=8192 conv=fsync
8192+0 records in
8192+0 records out
8589934592 bytes (8.6 GB, 8.0 GiB) copied, 44.923 s, 191 MB/s
# dd if=/dev/sda of=/dev/null bs=1M count=8192 conv=fsync
dd: fsync failed for '/dev/null': Invalid argument
8192+0 records in
8192+0 records out
8589934592 bytes (8.6 GB, 8.0 GiB) copied, 30.7414 s, 279 MB/s

Running the game on the exact same system with 16Gb of RAM and no swap works perfectly - even with multitasking - as we never end up filling physical RAM.

As there is some data missing though, should I still attempt to compile + run the program provided? I'm not quite clear on the mlock rlimit mention - I haven't really had to debug anything like this before.

Steven Haigh

📧 [email protected]       💻 http://www.crc.id.au
📞 +61 (3) 9001 6090    📱 0412 935 897

I have checked few gaps. E.g. vmstat.1503496391 vmstat.1503496451 which is one minute. The most notable thing is that there are only very few pagecache pages

			[base]		[diff]

nr_active_file 1641 3345
nr_inactive_file 1630 4787

So there is not much to reclaim without swap. The more important thing is that we keep reclaiming and refaulting that memory

workingset_activate 5905591 1616391
workingset_refault 33412538 10302135

pgactivate      	42279686        13219593
pgdeactivate    	48175757        14833350

pgscan_kswapd   	379431778       126407849
pgsteal_kswapd  	49751559        13322930

so we are effectivelly trashing over the very small amount of reclaimable memory. This is something that we cannot detect right now. It is even questionable whether the OOM killer would be an appropriate action. Your system has recovered and then it is always hard to decide whether a disruptive action is more appropriate. One minute of unresponsiveness is certainly annoying though. Your system is obviously under provisioned to load you want to run obviously.

It is quite interesting to see that we do not really have too many direct reclaimers during this time period

allocstall_normal       30      	1
allocstall_movable      490     	88
pgscan_direct_throttle  0       	0
pgsteal_direct  	24434   	4069
pgscan_direct   	38678   	5868

Swap IO tends to be really scattered and the IO performance is not really great even on a fast storage AFAIK.

Anyway your original report sounded like a regression. Were you able to run the _same_ workload on an older kernel without these issues?

Michal Hocko
SUSE Labs

--
To unsubscribe, send a message with 'unsubscribe linux-mm' in
the body to [email protected].  For more info on Linux MM,
see: http://www.linux-mm.org/ .
Don't email: <a href=mailto:"[email protected]"> [email protected] </a>

Yes, I understand that the system is really not suitable - however I believe the test is useful - even from an informational point of view :)

When I try the same tests with swap on an SSD under kernel 4.10.x (I believe the latest I tried was 4.10.25?) - then swap using the SSD did not cause any issues or periods of system unresponsiveness.

The file attached in the original bug report "vmstat-4.10.17-10Gb.log" was taken on my old system with 10Gb of RAM - and there were no significant pauses while swapping.

I do find it interesting that the newer '8Gb-swap-on-file.tar.gz' does not show any issues. I wonder if it would be helpful to attempt the same using a file on the SSD that was a swap disk in the '8Gb-swap-on-ssd.tar.gz' so we have a constant device - but with a file on the SSD instead of the entire block device. That would at least expose any issues on the same device in file vs block mode? Or maybe even if there's a difference just having the file on a much (much!) faster drive?

Steven Haigh

📧 [email protected]       💻 http://www.crc.id.au
📞 +61 (3) 9001 6090    📱 0412 935 897