The output results are inconsistent after each execution

[minhaics]

Version

v18.18.0

Platform

x64 window

Subsystem

No response

What steps will reproduce the bug?

let sleep_cpu_bound = function (time) {
    return new Promise((resolve, reject) => {
        var stop = new Date().getTime();
        while (new Date().getTime() < stop + time) {
            ;
        }
   
        return resolve(true)
    });
}
 
async function call_api_1() {
    try {
        console.log('entering the fetchData function');
 
        await sleep_cpu_bound(1000);
  
 
        const response_1 = await fetch('https://jsonplaceholder.typicode.com/posts/1');
 
        if (!response_1.ok) {
            throw new Error(`Error when calling API_1: ${response_1.status}`);
        }
 
        const data = await response_1.json();
        console.log('API_1 is coming');
 
        return data;
    } catch (error) {
        console.error('Error when calling API 1:', error);
        throw error;
    }
}
 
async function call_api_2() {
    try {
        console.log('entering the fetchSlowData function');
 
        const response_2 = await fetch('https://jsonplaceholder.typicode.com/comments/1');
        if (!response_2.ok) {
            throw new Error(`Error when calling API_2: ${response_2.status}`);
        }
 
        const data = await response_2.json();
        console.log('API_2 is coming');
        return data;
    } catch (error) {
        console.error('Error when calling API 2:', error);
        throw error;
    }
}
 
function checkings_1() {
    console.log('checking_1')
}
 
function checkings_2() {
    console.log('checking_2')
}
 
function checkings_3() {
    console.log('checking_3')
}
 
async function main() {
    const promise2 = call_api_2();
    console.log('promise_2', promise2);
    const promise1 = call_api_1();
    console.log('promise_1', promise1);
 
    checkings_1();
    checkings_2();
 
    //const [data2, data1] = await Promise.all([promise2, promise1]); // Wait for both promises to complete
 
    checkings_3();
    console.log('Ending');
}
 
main()

How often does it reproduce? Is there a required condition?

Occasionally, and inconsistently across executions.

What is the expected behavior? Why is that the expected behavior?

entering the fetchSlowData function
promise_2 Promise { }
entering the fetchData function
promise_1 Promise { }
checking_1
checking_2
checking_3
Ending
API_2 is coming
API_1 is coming

What do you see instead?

entering the fetchSlowData function
promise_2 Promise { }
entering the fetchData function
promise_1 Promise { }
checking_1
checking_2
checking_3
Ending
API_1 is coming
API_2 is coming

Additional information

hi You, in this piece of code, I intentionally want to notify 'API_2 is coming' first, so I placed the 'sleep()' function inside the 'call_api_1' function. However, when I run it on Node v18, I receive a strange result where sometimes 'API_2 is coming' appears first, and other times 'API_1 is coming' appears first on the screen. But when I check it in the Chrome browser, I consistently get the result 'API_2 is coming' first. I've tried to explain it, but I don't know the reason why. It seems to be a Node.js issue.

thank you!

[bnoordhuis]

Converted to a discussion because that's not a bug but a misunderstanding on your part.

You don't await the results of the async function calls, you Promise.all(...) them. That makes them run in parallel and they therefore complete in non-deterministic order.

[minhaics]

const fs = require('fs').promises;

// Function to generate large and heavy content
function generateHeavyContent(sizeInMB) {
    const content = 'This is some heavy content. '.repeat(10); // A line of content with a length of 1024 characters
    const iterations = Math.floor(sizeInMB * 1024 * 1024 / content.length); // Number of iterations to create the desired content size (MB * 1024 * 1024)
    return content.repeat(iterations);
}

// Asynchronous function to write heavy content to a file without blocking the main thread
async function writeHeavyFile(filePath, sizeInMB, index) {
    const heavyContent = generateHeavyContent(sizeInMB);
    console.log("starting timing");
    const startTime = process.hrtime();
    try {
        await fs.writeFile(filePath, heavyContent);
        const endTime = process.hrtime(startTime);
        const executionTimeInSeconds = endTime[0] + endTime[1] / 1e9; // Convert to seconds
        console.log('index', index);
        console.log(`Execution time: ${executionTimeInSeconds.toFixed(2)} seconds`);
        console.log(`File written successfully to ${filePath}`);
    } catch (error) {
        console.error(`Error writing file: ${error}`);
    }
}

sleepP = function (time) {
    return new Promise((resolve, reject) => {
        console.log('starting sleep')
        var stop = new Date().getTime();
        while (new Date().getTime() < stop + time) {
            ;
        }
        return resolve(true)
    });
}

// Using the function to write heavy content to files
const outputFile = 'heavy_file.txt'; // Output file name
const fileSizeInMB = 100; // Output file size (MB)

async function main() {
    for (let i = 0; i < 7; i++) {
        const outputFile = `heavy_file_${i}.txt`; // Using template literals to generate dynamic file names
        writeHeavyFile(outputFile, fileSizeInMB, i);
    }
    await sleepP(20000); // Sleep for 20 seconds
}

main();


//output:
// starting timing
// starting timing
// starting timing
// starting timing
// starting timing
// starting timing
// starting timing
// starting sleeP
// index 0
// Execution time: 29.98 seconds
// File written successfully to heavy_file_0.txt
// index 5
// Execution time: 29.28 seconds
// File written successfully to heavy_file_5.txt
// index 4
// Execution time: 29.43 seconds
// File written successfully to heavy_file_4.txt
// index 1
// Execution time: 29.85 seconds
// File written successfully to heavy_file_1.txt
// index 2
// Execution time: 29.74 seconds
// File written successfully to heavy_file_2.txt
// index 3
// Execution time: 30.22 seconds
// File written successfully to heavy_file_3.txt
// index 6
// Execution time: 29.81 seconds
// File written successfully to heavy_file_6.txt

[minhaics]

Dear friend @bnoordhuis, in this code snippet, I have made 7 writeHeavyFile functions run concurrently, and the main_thread is blocked by the sleepP function for a period of 20 seconds. This should be enough time for the writeHeavyFile functions to run in the background and complete file writing. However, I do not observe them running in the background as expected.

Even after the main_thread is unblocked, it seems that the 7 writeHeavyFile functions are still running on only one thread. I have tried setting "UV_THREADPOOL_SIZE=8" or "UV_THREADPOOL_SIZE=1," but the computation time remains the same.

This experiment suggests that the fs.writeFile(filePath, heavyContent) function does not use threads from the worker_pool. I hope you can help me clarify this issue.

Previously, I asked you whether the file read/write functions from fs module run in the background when the main thread is blocked. You said they do, and you also mentioned that they use threads from the worker pool, However, what I experimented with didn't yield the results as you described. Could you please correct my example or provide me with an example that helps me better understand what you mentioned earlier?

Thank you

[bnoordhuis]

fs.writeFile() round-trips through the thread pool operations at least three times: open file, write data, close file. You block the event loop after the first operation.

[minhaics]

Dear @bnoordhuis, you mentioned three activities: open file, write data, close file. To initiate any of these activities, does it require activation from the main thread? If the main thread is blocked, can they not be invoked? Could you tell me if the 'write data' operation is atomic? Does it write in chunks by default? If it writes in chunks, does it still preserve atomicity?

I can't think of a code example where a program can write a file while the event loop is being blocked. As you can see in the code snippet above, the worker pool only just 'opened the file' before 'writing data,' and I have tried to illustrate a code snippet that demonstrates that even though the event loop is blocked by a CPU-intensive task, file writing operations continue, but I can't find or think of any such code example.

[bnoordhuis]

does it require activation from the main thread? If the main thread is blocked, can they not be invoked?

Yes and yes.

the 'write data' operation is atomic?

I'm not sure what you mean by "atomic" here. In general partial data can be observed by other parties, because that's how most file systems work, they're not ACID databases.