1
2

sudo dd if=/dev/urandom of=/mnt/dm1/mapped.file bs=1G count=1
cp /mnt/dm1/mapped.file /tmp/mapped.file

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96

// TestMMap.java

import java.util.*;
import java.io.IOException;
import java.io.RandomAccessFile;
import java.nio.MappedByteBuffer;
import java.nio.channels.FileChannel;
import java.util.concurrent.ThreadLocalRandom;

public class TestMMap {

   public static void main(String[] arg) throws Exception {
        TestGCLog l = new TestGCLog();
        l.start();

        TestMMap t = new TestMMap();
        t.test(arg[0]);
   }

   void test(String mapfile) throws Exception {
        long startTime = System.currentTimeMillis();
        RandomAccessFile file = new RandomAccessFile(mapfile, "r");
        FileChannel channel = file.getChannel();

        // Read file into mapped buffer
        MappedByteBuffer mbb =
                channel.map(FileChannel.MapMode.READ_ONLY,
                        0,          // position
                        channel.size());

        long lastprint = System.currentTimeMillis();

        while(true) {
            // for (int i = 0; i < channel.size(); i++) {
                long now = System.currentTimeMillis();
                // System.out.print((char) mbb.get());
                long p = ThreadLocalRandom.current().nextLong(0, channel.size() - 1);
                mbb.position((int)p);
                mbb.get();
                if( System.currentTimeMillis() - now > 1 * 1000 ) {
                    System.out.println( new Date() + " - Read MMap: read slow: " + mbb.position() + "@" + mbb.limit() + " ," + (System.currentTimeMillis() - now) + "ms" );
                }
                else if( now - lastprint > 5 * 1000 ) {
                    System.out.println( new Date() + " - Read MMap:" + mbb.position() + "/" + mbb.limit() );
                    lastprint = now;
                }
                Thread.sleep(10);
            // }
            // mbb.position(0);
            if(false)
                break;
        }

        channel.close();
        file.close();
        System.out.println("Total read and print time: " + (System.currentTimeMillis() - startTime));
   }

    static class TestGCLog extends Thread {
        List objList = new ArrayList();
        byte[] m = new byte[100*1024];

        public TestGCLog() {
            super("TestGCLog");
        }
        
        @Override
        public void run() {
            try {
                test();
            } catch (Exception e) {
                e.printStackTrace();
            }
        }

        void test() throws Exception {
            long lastprint = System.currentTimeMillis();
            while(true) {
                objList.clear();
                long start = System.currentTimeMillis();
                TestGCLog newObj = new TestGCLog();
                long end = System.currentTimeMillis();
                if( end - start > 10 ) {
                    System.out.println( new Date() + " - TestGCLog: slow new object: " + (end - start) + "ms"  );
                }                
                objList.add( newObj );
                Thread.sleep(5);
                long now = System.currentTimeMillis();
                if( now - lastprint > 5 * 1000 ) {
                    System.out.println( new Date() + " - TestGCLog" );
                    lastprint = now;
                }
            }
        }
    }
}

  1
  2
  3
  4
  5
  6
  7
  8
  9
 10
 11
 12
 13
 14
 15
 16
 17
 18
 19
 20
 21
 22
 23
 24
 25
 26
 27
 28
 29
 30
 31
 32
 33
 34
 35
 36
 37
 38
 39
 40
 41
 42
 43
 44
 45
 46
 47
 48
 49
 50
 51
 52
 53
 54
 55
 56
 57
 58
 59
 60
 61
 62
 63
 64
 65
 66
 67
 68
 69
 70
 71
 72
 73
 74
 75
 76
 77
 78
 79
 80
 81
 82
 83
 84
 85
 86
 87
 88
 89
 90
 91
 92
 93
 94
 95
 96
 97
 98
 99
100
101
102
103
104
105
106
107
108
109
110
111
112

#!/usr/local/bin/bpftrace

// trace-safepoint-mmap2.bt
// 程序假设环境中只有一个 java 进程

BEGIN
{}

uprobe:/usr/lib/jvm/java-17-openjdk-amd64/lib/server/libjvm.so:*SafepointSynchronize*begin*
{
    // printf("java elf main. PID=%d", pid);
    @java_pid[pid] = pid;
}

uprobe:/usr/lib/jvm/java-17-openjdk-amd64/lib/server/libjvm.so:*SafepointSynchronize*begin*
/@java_pid[pid]/
{
    @sp_begin[pid, tid, comm, ustack] = count();
    @vm_thread_tid[tid] = tid;
    @vm_thread_waiting_sp_sync[tid] = tid;
    @vm_thread_in_STW[tid] = tid;
    @STWing[pid] = pid;
    printf("%d %-6d %-16s SafepointSynchronize::begin \n", elapsed / 1e6, tid, comm);
}

uprobe:/usr/lib/jvm/java-17-openjdk-amd64/lib/server/libjvm.so:*RuntimeService*record_safepoint_synchronized*
/@java_pid[pid]/
{
    @sp_synchronized[tid, comm, ustack] = count();
    delete (@vm_thread_waiting_sp_sync[tid]);
    delete (@STWing[pid]);
    printf("%d %-6d %-16s RuntimeService::record_safepoint_synchronized\n", elapsed / 1e6, tid, comm);
}

uretprobe:/usr/lib/jvm/java-17-openjdk-amd64/lib/server/libjvm.so:*SafepointSynchronize*end*
/@java_pid[pid]/
{
    delete (@vm_thread_in_STW[tid]);
    printf("%d %-6d %-16s SafepointSynchronize::end\n", elapsed / 1e6, tid, comm);
    printf("===========\n\n");
}


// tracepoint:exceptions:page_fault_user
// /@java_pid[pid]/
// {
//     @page_fault_user[tid, comm, kstack(8)] = count();
// 	printf("%d page_fault_user(\"%s %d\", address=0x%lX, ip=0x%lX)\n", elapsed / 1e6, comm, tid, args->address, args->ip);
// }

kprobe:filemap_fault
/@java_pid[pid]/
{
    @filemap_fault[tid, comm, kstack(8)] = count();
	printf("%d %-6d %-16s filemap_fault()\n", elapsed / 1e6, tid, comm);

    @filemap_fault_kstack[ tid, comm, kstack(8)] = count();
    @filemap_fault_ustack[ tid, comm, ustack(8)] = count();
}

kretfunc:filemap_fault
/@java_pid[pid]/
{
	printf("%d %-6d %-16s kretfunc:filemap_fault()\n", elapsed / 1e6, tid, comm);
}

// tracepoint:block:block_rq_complete,
// tracepoint:block:block_bio_complete
// /@java_pid[pid]/
// {
// 	@block_bio_complete[pid, tid, comm, kstack(8)] = count();
// }

kretfunc:ext4_mpage_readpages
/@java_pid[pid]/
{
    $page = args->page;
    $node = args->inode;
    $rac = args->rac;
    $nr_pages = $rac->_nr_pages;
    printf ("%d %-6d %-16s kretfunc:ext4_mpage_readpages %ld %s\n", elapsed / 1e6, tid, comm, $rac->_index * 4096, str($rac->file->f_path.dentry->d_name.name));
    @ext4_mpage_readpages[ tid, comm, kstack(8)] = count();
    // @ext4_mpage_readpages_ustack[ tid, comm, ustack(8)] = count();
}

// kprobe:ext4_mpage_readpages
// /@java_pid[pid]/
// {
//     printf ("%d kprobe:ext4_mpage_readpages %d %s\n", elapsed / 1e6, tid, comm);
// }


// tracepoint:syscalls:sys_enter_sync,
// tracepoint:syscalls:sys_enter_syncfs,
// tracepoint:syscalls:sys_enter_fsync,
// tracepoint:syscalls:sys_enter_fdatasync,
// tracepoint:syscalls:sys_enter_sync_file_range*,
// tracepoint:syscalls:sys_enter_msync
// /@java_pid[pid]/
// {
// 	time("%H:%M:%S  ");
// 	printf("sync syscall: %-6d %-16s %s\n", pid, comm, probe);

//     // if(  @vm_thread_waiting_sp_sync[tid] ) {
//         @sync_call[pid, tid, comm, probe, ustack(6)] = count();
//         printf("sp sync_call: %-6d %-16s %s\n", pid, comm, probe);
//     // }

// }

END
{}

1

env LD_LIBRARY_PATH=/lib/libc6-prof/x86_64-linux-gnu /usr/lib/jvm/java-17-openjdk-amd64/bin/java '-Xlog:safepoint,gc=info:stdout:level,tags,time,uptime,pid' -XX:+UnlockDiagnosticVMOptions -XX:+PreserveFramePointer -Xms128M -Xmx128M -XX:+AlwaysPreTouch -cp . TestMMap /mnt/dm1/mapped.file

1

sudo bpftrace ./trace-safepoint-mmap2.bt

1

env LD_LIBRARY_PATH=/lib/libc6-prof/x86_64-linux-gnu /usr/lib/jvm/java-17-openjdk-amd64/bin/java '-Xlog:safepoint,gc=info:stdout:level,tags,time,uptime,pid' -XX:+UnlockDiagnosticVMOptions -XX:+PreserveFramePointer -Xms128M -Xmx128M -XX:+AlwaysPreTouch -cp . TestMMap /tmp/mapped.file

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16

apiVersion: v1
kind: Pod
metadata:
  annotations:
  labels:
  name: xyz
spec:
  containers:
  - command: java ... -Xloggc:/usr/share/myapp/logs/gc.log ...
    ...
    volumeMounts:
    - mountPath: /usr/share/myapp/logs
      name: myapp-logs
  volumes:
  - emptyDir: {}
    name: myapp-logs

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27

# load the brd kernel module. rd_nr is the maximum number of ramdisks. rd_size is the ramdisk size in KB.
sudo modprobe brd rd_nr=1 rd_size=1048576

ls -l /dev/ram0
brw-rw---- 1 root disk 1, 0 Aug 24 20:00 /dev/ram0

sudo blockdev --getsize /dev/ram0 # Display the size in 512-byte sectors
2097152

#We specify the read write delay as 200ms, specify the write latency(e.g. 100ms) as below.
size=$(sudo blockdev --getsize /dev/ram0)
sudo dmsetup remove delayed
echo "0 $size delay /dev/ram0 0 200" | sudo dmsetup create delayed


sudo dmsetup table delayed
0 2097152 delay 1:0 0 50

ls -la /dev/mapper/ | grep delayed
lrwxrwxrwx  1 root root       7 May 19 18:37 delayed -> ../dm-0

sudo mkfs.ext4 /dev/dm-0

sudo mkdir /mnt/dm1
sudo mount /dev/dm-0 /mnt/dm1

cd /mnt/dm1

1
2
3
4
5

# 挂起
sudo dmsetup suspend /dev/$your_dm_dev

# 恢复
sudo dmsetup resume /dev/$your_dm_dev