[SPDK] A issue about maximums of write latency when we access the same block consecutively.

[-- Attachment #1: Type: text/plain, Size: 2545 bytes --]

Hi, all
Recently, we use a demo to obverse the latency.
The demo is based on 'hello_world.c' in 'spdk/examples/nvme/hello_world'.
The modifications are described as following.
---------------------------------------------------------------------------------------------------------------------------------------------------------------
static void write_complete(void *arg, const struct spdk_nvme_cpl *completion) {
    struct hello_world_sequence   *sequence = arg;
    spdk_free(sequence->buf);
    sequence->is_completed = 1;
}
---------------------------------------------------------------------------------------------------------------------------------------------------------------
hello_world(int id) {
...
    clock_gettime(CLOCK_REALTIME, &time1);
    rc = spdk_nvme_ns_cmd_write(ns_entry->ns, ns_entry->qpair, sequence.buf,
                                                       id, /* LBA start */ 
                                                      1, /* number of LBAs */
                                                       write_complete, &sequence, 0);
...
    while (!sequence.is_completed)  {
            spdk_nvme_qpair_process_completions(ns_entry->qpair, 0);
     }
     clock_gettime(CLOCK_REALTIME, &time2);
     printf("%ld \n", diff(time1,time2).tv_nsec);
...
}
---------------------------------------------------------------------------------------------------------------------------------------------------------------
int main() {
... 
   int i = 500;
    while (i > 0) {
            if (i-- % 4 == 0) {
                 id += 10;
            }
            hello_world(id);
    }
...
}
---------------------------------------------------------------------------------------------------------------------------------------------------------------
We find that when we access the same block consecutively, the occurrence of maximum latencies will become more frequent. 
Additionally,  they can reach even 2-3 ms and present a periodical change. 
The related experiment results can be seen in accessory 'result'. The results are like:
 Why?
(1) As shown in the file 'result', for the same block, the latency of the first accessing is about 10-12 μs while the second, third and the forth accessing can reach 700-900 μs even 2-3 ms? 
     I want to know the reason why the operation difference between the first accessing and the others exists.
(2) Why the maximums of 2-3 ms have a periodical change as shown in the above figure?


  Best wishes,
  Jiajia Chu

[-- Attachment #2: attachment.html --]
[-- Type: text/html, Size: 4188 bytes --]

[-- Attachment #3: aaa.jpg --]
[-- Type: image/jpeg, Size: 2997763 bytes --]

[-- Attachment #4: result.obj --]
[-- Type: application/octet-stream, Size: 4850 bytes --]

EAL: Detected 40 lcore(s)
EAL: Auto-detected process type: PRIMARY
EAL: No free hugepages reported in hugepages-1048576kB
EAL: Probing VFIO support...
EAL: PCI device 0000:06:00.0 on NUMA socket 0
EAL:   probe driver: 8086:953 spdk_nvme
EAL: PCI device 0000:07:00.0 on NUMA socket 0
EAL:   probe driver: 8086:953 spdk_nvme
Initializing NVMe Controllers
EAL: PCI device 0000:06:00.0 on NUMA socket 0
EAL:   probe driver: 8086:953 spdk_nvme
Attaching to 0000:06:00.0
EAL: PCI device 0000:07:00.0 on NUMA socket 0
EAL:   probe driver: 8086:953 spdk_nvme
Attaching to 0000:07:00.0
Attached to 0000:06:00.0
Using controller INTEL SSDPECME032T4  (CVF8547400EL3P2CGN-1) with 1 namespaces.
  Namespace ID: 1 size: 1600GB
Attached to 0000:07:00.0
Using controller INTEL SSDPECME032T4  (CVF8547400EL3P2CGN-2) with 1 namespaces.
  Namespace ID: 1 size: 1600GB
Initialization complete.
578399 
627879 
905910 
837393 
11471 
700092 
912493 
838944 
11584 
701555 
843587 
842619 
10645 
771692 
841840 
908734 
11367 
701584 
908298 
807404 
11041 
706581 
841209 
842818 
36212 
646781 
815384 
812124 
10798 
700494 
844009 
1607305 
11832 
704208 
908099 
907596 
10538 
705744 
861717 
822366 
14275 
697649 
942942 
910912 
10215 
771716 
909750 
872705 
11281 
772450 
907437 
910800 
11122 
771479 
913026 
910220 
89390 
662337 
909971 
906250 
10535 
768601 
903570 
904516 
11360 
736202 
909135 
906195 
11013 
769150 
909958 
908431 
10507 
805149 
910051 
906410 
9597 
735814 
943164 
911742 
10949 
2921442 
2990648 
2929058 
10868 
3052099 
2929099 
2960655 
10946 
2741933 
2859248 
3190659 
10795 
2891705 
3027894 
3093697 
11312 
3053440 
2796344 
2857903 
15189 
60041 
842576 
815144 
8911 
690323 
861399 
790160 
8798 
692363 
848078 
916440 
9968 
721094 
848282 
813205 
8849 
756824 
849552 
817706 
9118 
685775 
798765 
880288 
8239 
685569 
849474 
848680 
9102 
725363 
850520 
814352 
8814 
661112 
847351 
845621 
8776 
658597 
852557 
815763 
8637 
721205 
951891 
915204 
9186 
790936 
849939 
823263 
8878 
717462 
846285 
914700 
8768 
791119 
806713 
841805 
8620 
790915 
846406 
877685 
8977 
759485 
913598 
914523 
8847 
793607 
915836 
813466 
9287 
786108 
916540 
851126 
8701 
727961 
915065 
848209 
8621 
723374 
943375 
854388 
8948 
2843957 
3129337 
3167804 
11156 
2833548 
3065357 
3123325 
9674 
2709908 
3066700 
2898656 
9000 
2711598 
3098088 
2932727 
9083 
2876809 
3067148 
3136661 
9445 
2798517 
2937410 
2828013 
12717 
751586 
2925563 
2977357 
10485 
3022226 
2861060 
2928720 
10725 
3092796 
2995656 
2959634 
10586 
2891287 
3029278 
2978744 
9834 
2860501 
3229775 
2993495 
10322 
2881087 
2997150 
2997206 
11680 
2892875 
2796735 
2996026 
10694 
2777882 
2931152 
2927744 
9399 
2754641 
2947965 
2995322 
10690 
2857909 
2861345 
2826033 
11089 
2759787 
2898713 
2830202 
10141 
2763660 
2697726 
2694289 
12058 
2857148 
2992986 
3027870 
10709 
2825695 
2860569 
2894848 
11875 
2892414 
2934415 
840244 
11426 
706501 
844426 
909611 
10324 
696709 
805883 
841287 
11300 
658565 
905693 
843638 
10190 
690019 
844678 
874235 
11113 
672904 
821171 
796841 
26545 
603991 
837883 
843716 
11839 
669807 
839930 
838525 
11008 
670258 
810951 
843516 
10403 
673710 
826949 
845045 
10682 
714685 
840581 
909143 
11568 
52565 
3094342 
2967298 
8885 
2879380 
2966165 
2997362 
8675 
2875300 
2801773 
3065171 
8586 
2886870 
2904994 
3126807 
9209 
2908824 
2902670 
2867949 
8769 
2547333 
2721576 
2834544 
9485 
2544404 
2934658 
2769151 
9234 
2612107 
2701303 
2966823 
9438 
2611603 
2800440 
2800576 
8636 
2580223 
2900025 
2833152 
9015 
2760412 
2735484 
2767416 
8814 
2801794 
2864001 
2668729 
8996 
2810770 
2649450 
2807850 
9019 
2779255 
2793581 
847331 
9879 
677229 
814258 
843209 
9092 
684278 
808301 
808814 
9407 
780840 
809448 
803590 
8556 
673711 
807511 
837984 
9173 
682692 
809983 
836602 
8771 
744812 
791488 
842810 
8816 
713337 
853851 
826364 
8753 
677448 
809705 
797800 
9738 
683720 
808645 
843893 
8499 
682338 
807833 
937091 
9168 
776193 
906420 
836243 
9023 
681016 
843287 
826765 
14769 
61883 
925356 
906256 
18237 
642868 
830139 
903435 
10249 
772422 
843322 
874604 
10119 
763203 
911613 
908964 
13556 
705753 
841360 
822748 
10038 
774141 
840083 
908594 
10763 
705537 
843154 
910711 
10007 
771118 
946150 
842905 
10669 
706851 
871806 
956606 
10295 
762283 
3119618 
2990178 
10188 
2759875 
3291427 
2932225 
11920 
2825092 
2960664 
2959704 
10115 
3056410 
3027189 
3127736 
9580 
2959419 
3192336 
2789758 
14167 
2855895 
2928339 
2928103 
11438 
2957086 
3292255 
2894909 
10094 
2859753 
2995448 
2928224 
9707 
2820687 
3027967 
2931493 
11449 
2922926 
2993807 
3032904 
23598 
2827235 
3028553 
2981587 
9997 
2846871 
3068628 
2783704 
10053 
2858511 
2925205 
2929744 
11193 
2788741 
2883847 
2960650