Repository: pytorch
Issue: Certain operations cause implicity sync-points
Labels: module: cuda,triaged

## 🐛 Bug

<!-- A clear and concise description of what the bug is. -->

When profiling networks I've found that certain functions seem to cause the CUDA backend to synchronize with the host. 

This is similar to #1989 but is applicable to a wider variety of functions, which I believe shouldn't cause syncs, but they seem to. 

Even if these operations do implicitly cause syncs it would be nice to have a list of which functions do this in the docs (or perhaps someone can point me to this if this already exists). 

## To Reproduce

I have a MWE showing several functions that do and do not cause implicit sync points. The basic idea is I create some data, and run it through some busy work operations that do not cause syncing (i.e. convolutions), then I run it through an operation to test if it syncs. Finally, I run it through a few more busy work ops and then force a synchronization at the end. I run a line profile to check how long each call takes. If the operation causes a sync, then it will show up as taking time in the profiler, otherwise if there is no implicit syncing, then the bulk of time should be taken up by the final explicit sync. 

The operation that I test first is uint8 masking (i.e. masked_select / __getitem__) (which is how I first uncovered the issue)

```python
import torch


def main():

    def profile_onthefly(func):
        def _wrapper(*args, **kw):
            import line_profiler
            from six.moves import cStringIO
            profile = line_profiler.LineProfiler()

            result = profile(func)(*args, **kw)

            file_ = cStringIO()
            profile.print_stats(stream=file_, stripzeros=True)
            file_.seek(0)
            text = file_.read()
            print(text)
            return result
        return _wrapper

    def test_syncpoint_mask(data, conv2d, do_mask=False, do_sync=False):
        print('---------')
        print(' * do_mask = {!r}'.format(do_mask))
        print(' * do_sync = {!r}'.format(do_sync))

        torch.cuda.synchronize()

        x = data
        N = 10
        # Do some busy work
        for i in range(N):
            x = conv2d(x)

        # Create a mask
        mask = (data > .5).view(-1)
        x = x.view(-1)
        if do_mask:
            x = x[mask]

        if do_sync:
            torch.cuda.synchronize()

        # Do more busy work
        for i in range(N):
            x = x * x
            x = torch.sqrt(x)

        torch.cuda.synchronize()

    xpu = torch.device(0)
    # Setup dummy data
    bsize = 128
    data = torch.rand(bsize, 3, 512, 512).to(xpu)
    conv2d = torch.nn.Conv2d(in_channels=3, out_channels=3, kernel_size=3, padding=1).to(xpu)

    # Profile to show how masking causes an implicity sync-point

    profile_onthefly(test_syncpoint_mask)(data, conv2d, do_mask=True, do_sync=False)

    profile_onthefly(test_syncpoint_mask)(data, conv2d, do_mask=False, do_sync=False)

    profile_onthefly(test_syncpoint_mask)(data, conv2d, do_mask=False, do_sync=True)
```

The final three lines run the test function in 3 different ways. 

The first line (`profile_onthefly(test_syncpoint_mask)(data, conv2d, do_mask=True, do_sync=False)`) shows that if we do a mask, but we don't do an internal sync, then there is a bulk of time taken up by the masking operation (suggesting that an implicit sync is occurring). 

```python
---------
 * do_mask = True
 * do_sync = False
Timer unit: 1e-06 s

Total time: 0.261704 s
File: /home/joncrall/_torch_sync_mwe.py
Function: test_syncpoint_mask at line 22

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
    22                                               def test_syncpoint_mask(data, conv2d, do_mask=False, do_sync=False):
    23         1         27.0     27.0      0.0          print('---------')
    24         1          8.0      8.0      0.0          print(' * do_mask = {!r}'.format(do_mask))
    25         1          4.0      4.0      0.0          print(' * do_sync = {!r}'.format(do_sync))
    26                                           
    27         1         88.0     88.0      0.0          torch.cuda.synchronize()
    28                                           
    29         1          1.0      1.0      0.0          x = data
    30         1          1.0      1.0      0.0          N = 10
    31                                                   # Do some busy work
    32        11         15.0      1.4      0.0          for i in range(N):
    33        10      10231.0   1023.1      3.9              x = conv2d(x)
    34                                           
    35                                                   # Create a mask
    36         1        455.0    455.0      0.2          mask = (data > .5).view(-1)
    37         1         16.0     16.0      0.0          x = x.view(-1)
    38         1          1.0      1.0      0.0          if do_mask:
    39         1     222128.0 222128.0     84.9              x = x[mask]
    40                                           
    41         1          1.0      1.0      0.0          if do_sync:
    42                                                       torch.cuda.synchronize()
    43                                           
    44                                                   # Do more busy work
    45        11         13.0      1.2      0.0          for i in range(N):
    46        10        297.0     29.7      0.1              x = x * x
    47        10       2895.0    289.5      1.1              x = torch.sqrt(x)
    48                                           
    49         1      25523.0  25523.0      9.8          torch.cuda.synchronize()
```
We can see that in this case 84.9% of the time is spent on the mask operation because it is actually waiting for all those convolutions to finish.


The next line (`profile_onthefly(test_syncpoint_mask)(data, conv2d, do_mask=False, do_sync=False)`), verifies that if we do neither a mask or a sync, then the majority of time is indeed taken up by the final explicit sync call. 

```python
---------
 * do_mask = False
 * do_sync = False
Timer unit: 1e-06 s

Total time: 0.233294 s
File: /home/joncrall/_torch_sync_mwe.py
Function: test_syncpoint_mask at line 22

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
    22                                               def test_syncpoint_mask(data, conv2d, do_mask=False, do_sync=False):
    23         1          8.0      8.0      0.0          print('---------')
    24         1          7.0      7.0      0.0          print(' * do_mask = {!r}'.format(do_mask))
    25         1          5.0      5.0      0.0          print(' * do_sync = {!r}'.format(do_sync))
    26                                           
    27         1         14.0     14.0      0.0          torch.cuda.synchronize()
    28                                           
    29         1          1.0      1.0      0.0          x = data
    30         1          1.0      1.0      0.0          N = 10
    31                                                   # Do some busy work
    32        11         12.0      1.1      0.0          for i in range(N):
    33        10       1091.0    109.1      0.5              x = conv2d(x)
    34                                           
    35                                                   # Create a mask
    36         1         32.0     32.0      0.0          mask = (data > .5).view(-1)
    37         1          8.0      8.0      0.0          x = x.view(-1)
    38         1          0.0      0.0      0.0          if do_mask:
    39                                                       x = x[mask]
    40                                           
    41         1          0.0      0.0      0.0          if do_sync:
    42                                                       torch.cuda.synchronize()
    43                                           
    44                                                   # Do more busy work
    45        11         16.0      1.5      0.0          for i in range(N):
    46        10        254.0     25.4      0.1              x = x * x
    47        10       5359.0    535.9      2.3              x = torch.sqrt(x)
    48                                           
    49         1     226486.0 226486.0     97.1          torch.cuda.synchronize()
```
In this case 97% of the time is taken up by the final synchronize operation, which means that no intermediate syncing has taken place, all the work is done in a lazy fashion, so the final sync eats up all the time. 


Finally the final line `profile_onthefly(test_syncpoint_mask)(data, conv2d, do_mask=False, do_sync=True)`, shows that if we force an intermediate sync (without masking), we get a similar performance time as if we did the mask. 

```python
---------
 * do_mask = False
 * do_sync = True
Timer unit: 1e-06 s

Total time: 0.233516 s
File: /home/joncrall/_torch_sync_mwe.py
Function: test_syncpoint_mask at line 22

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
    22                                               def test_syncpoint_mask(data, conv2d, do_mask=False, do_sync=False):
    23         1          8.0      8.0      0.0          print('---------')
    24         1          7.0      7.0      0.0          print(' * do_mask = {!r}'.format(do_mask))
    25         1          5.0      5.0      0.0          print(' * do_sync = {!r}'.format(do_sync))
    26                                           
    27         1         13.0     13.0      0.0          torch.cuda.synchronize()
    28                                           
    29         1          1.0      1.0      0.0          x = data
    30         1          0.0      0.0      0.0          N = 10
    31                                                   # Do some busy work
    32        11         14.0      1.3      0.0          for i in range(N):
    33        10       1093.0    109.3      0.5              x = conv2d(x)
    34                                           
    35                                                   # Create a mask
    36         1         34.0     34.0      0.0          mask = (data > .5).view(-1)
    37         1          8.0      8.0      0.0          x = x.view(-1)
    38         1          0.0      0.0      0.0          if do_mask:
    39                                                       x = x[mask]
    40                                           
    41         1          1.0      1.0      0.0          if do_sync:
    42         1     183895.0 183895.0     78.8              torch.cuda.synchronize()
    43                                           
    44                                                   # Do more busy work
    45        11         10.0      0.9      0.0          for i in range(N):
    46        10        220.0     22.0      0.1              x = x * x
    47        10        232.0     23.2      0.1              x = torch.sqrt(x)
    48                                           
    49         1      47975.0  47975.0     20.5          torch.cuda.synchronize()
```
In this case we see if we replace the mask with a explicit sync, that takes up 78% of the time, which is similar to the 84% of the time we saw with the masking operation. 

------------------------------

I test this for a few other operations as well

```python
    # --- There seem to be a few operations that cause implicity syncs

    def test_synpoint_other(opname, op):
        def test_syncpoint_(data, conv2d):
            print('---------')
            print('opname = {!r}'.format(opname))
            torch.cuda.synchronize()
            x = data
            N = 10
            for i in range(N):
                x = conv2d(x)  # non-syncing busy work
            op(x)
            # Do more busy work
            for i in range(N):
                x = torch.sqrt(x * x)  # non-syncing busy work
            torch.cuda.synchronize()
        profile_onthefly(test_syncpoint_)(data, conv2d)

    test_synpoint_other('sum', lambda x: x.sum())
    test_synpoint_other('sum(dim=0)', lambda x: x.sum(dim=0))
    test_synpoint_other('sigmoid', lambda x: x.sigmoid())
```

A simple sum will cause an  implicit sync
```python
opname = 'sum'
Timer unit: 1e-06 s

Total time: 0.221028 s
File: /home/joncrall/_torch_sync_mwe.py
Function: test_syncpoint_ at line 68

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
    68                                                   def test_syncpoint_(data, conv2d):
    69         1          9.0      9.0      0.0              print('---------')
    70         1          8.0      8.0      0.0              print('opname = {!r}'.format(opname))
    71         1         13.0     13.0      0.0              torch.cuda.synchronize()
    72         1          1.0      1.0      0.0              x = data
    73         1          1.0      1.0      0.0              N = 10
    74        11         12.0      1.1      0.0              for i in range(N):
    75        10       1148.0    114.8      0.5                  x = conv2d(x)  # non-syncing busy work
    76         1     174351.0 174351.0     78.9              op(x)
    77                                                       # Do more busy work
    78        11          9.0      0.8      0.0              for i in range(N):
    79        10        455.0     45.5      0.2                  x = torch.sqrt(x * x)  # non-syncing busy work
    80         1      45021.0  45021.0     20.4              torch.cuda.synchronize()
```

However, a `sum(dim=0)` and a `sigmoid` call will not. 

```python
---------
opname = 'sum(dim=0)'
Timer unit: 1e-06 s

Total time: 0.221 s
File: /home/joncrall/_torch_sync_mwe.py
Function: test_syncpoint_ at line 68

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
    68                                                   def test_syncpoint_(data, conv2d):
    69         1          8.0      8.0      0.0              print('---------')
    70         1          7.0      7.0      0.0              print('opname = {!r}'.format(opname))
    71         1         13.0     13.0      0.0              torch.cuda.synchronize()
    72         1          1.0      1.0      0.0              x = data
    73         1          1.0      1.0      0.0              N = 10
    74        11         11.0      1.0      0.0              for i in range(N):
    75        10       1099.0    109.9      0.5                  x = conv2d(x)  # non-syncing busy work
    76         1         92.0     92.0      0.0              op(x)
    77                                                       # Do more busy work
    78        11         10.0      0.9      0.0              for i in range(N):
    79        10        421.0     42.1      0.2                  x = torch.sqrt(x * x)  # non-syncing busy work
    80         1     219337.0 219337.0     99.2              torch.cuda.synchronize()


---------
opname = 'sigmoid'
Timer unit: 1e-06 s

Total time: 0.222286 s
File: /home/joncrall/_torch_sync_mwe.py
Function: test_syncpoint_ at line 68

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
    68                                                   def test_syncpoint_(data, conv2d):
    69         1         24.0     24.0      0.0              print('---------')
    70         1         24.0     24.0      0.0              print('opname = {!r}'.format(opname))
    71         1         13.0     13.0      0.0              torch.cuda.synchronize()
    72         1          0.0      0.0      0.0              x = data
    73         1          1.0      1.0      0.0              N = 10
    74        11         12.0      1.1      0.0              for i in range(N):
    75        10       1088.0    108.8      0.5                  x = conv2d(x)  # non-syncing busy work
    76         1         83.0     83.0      0.0              op(x)
    77                                                       # Do more busy work
    78        11         11.0      1.0      0.0              for i in range(N):
    79        10        419.0     41.9      0.2                  x = torch.sqrt(x * x)  # non-syncing busy work
    80         1     220611.0 220611.0     99.2              torch.cuda.synchronize()
```

Instead of increasing the length of this report, I'll simply summarize the rest. 

Ops that did cause implicit sync:
* masked_select
* nonzero
* sum(dim=None)

Ops that did not cause implicit sync:
* sum(dim=<Int>)
* conv
* reshape
* squeeze
* sigmoid
* arithmetic operations `+ - / * `

## Expected behavior

Obviously there are lots of operations I didn't test, so it would be nice to have an understanding of when I should expect an operation to cause an implicit sync and when I shouldn't.

I expect its something to do with operations which have clearly defined input and output shapes, but having something more than my hunches would be nice. Also, perhaps this is a bug, and masked_select should actually not force a sync. 

## Environment

```
PyTorch version: 1.0.0.dev20181008
Is debug build: No
CUDA used to build PyTorch: 9.2.148

OS: Ubuntu 18.04.1 LTS
GCC version: (Ubuntu 7.3.0-27ubuntu1~18.04) 7.3.0
CMake version: version 3.12.0

Python version: 3.6
Is CUDA available: Yes
CUDA runtime version: 9.2.148
GPU models and configuration: 
GPU 0: GeForce GTX 1080 Ti
GPU 1: GeForce GTX 1080 Ti

Nvidia driver version: 396.54
cuDNN version: Could not collect

Versions of relevant libraries:
[pip] Could not collect
[conda] Could not collect
```

cc @ngimel